{
 "cells": [
  {
   "cell_type": "markdown",
   "id": "89795401",
   "metadata": {},
   "source": [
    "# Demo: Knowledge Graph Completion\n",
    "\n",
    "In this tutorial demo, we will use the Graph4NLP library to build a GNN-based knowledge graph completion model. The model consists of\n",
    "\n",
    "+ graph embedding module (e.g., GGNN)\n",
    "+ predictoin module (e.g., DistMult decoder)\n",
    "\n",
    "We will use the built-in module APIs to build the model, and evaluate it on the Kinship dataset.\n",
    "\n",
    "## Environment setup\n",
    "\n",
    "Please follow the instructions [here](https://github.com/graph4ai/graph4nlp_demo#environment-setup) to set up the environment. Please also run the following commands to install extra packages used in this demo.\n",
    "```\n",
    "pip install spacy\n",
    "python -m spacy download en_core_web_sm\n",
    "pip install h5py\n",
    "pip install future\n",
    "```\n",
    "\n",
    "This notebook was tested on :\n",
    "\n",
    "```\n",
    "torch == 1.9.0\n",
    "torchtext == 0.10.0\n",
    "spacy == 3.0.8\n",
    "```"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "37ce49b6",
   "metadata": {},
   "source": [
    "# Data preprocessing for KGC\n",
    "+ Run the preprocessing script for WN18RR and Kinship: ```sh kg_completion/preprocess.sh```\n",
    "+ You can now run the model"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 2,
   "id": "ce7542fa",
   "metadata": {},
   "outputs": [],
   "source": [
    "import torch\n",
    "import numpy as np\n",
    "import torch.backends.cudnn as cudnn\n",
    "\n",
    "from evaluation import ranking_and_hits\n",
    "from model import ConvE, Distmult, Complex, GGNNDistMult, GCNDistMult, GCNComplex\n",
    "\n",
    "from spodernet.preprocessing.pipeline import DatasetStreamer\n",
    "from spodernet.preprocessing.processors import JsonLoaderProcessors, Tokenizer, AddToVocab, SaveLengthsToState, StreamToHDF5, SaveMaxLengthsToState, CustomTokenizer\n",
    "from spodernet.preprocessing.processors import ConvertTokenToIdx, ApplyFunction, ToLower, DictKey2ListMapper, ApplyFunction, StreamToBatch\n",
    "from spodernet.utils.global_config import Config, Backends\n",
    "from spodernet.utils.logger import Logger, LogLevel\n",
    "from spodernet.preprocessing.batching import StreamBatcher\n",
    "from spodernet.preprocessing.pipeline import Pipeline\n",
    "from spodernet.preprocessing.processors import TargetIdx2MultiTarget\n",
    "from spodernet.hooks import LossHook, ETAHook\n",
    "from spodernet.utils.util import Timer\n",
    "from spodernet.preprocessing.processors import TargetIdx2MultiTarget\n",
    "import argparse\n",
    "\n",
    "np.set_printoptions(precision=3)\n",
    "cudnn.benchmark = True"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 3,
   "id": "96061fff",
   "metadata": {},
   "outputs": [],
   "source": [
    "''' Preprocess knowledge graph using spodernet. '''\n",
    "def preprocess(dataset_name, delete_data=False):\n",
    "    full_path = 'data/{0}/e1rel_to_e2_full.json'.format(dataset_name)\n",
    "    train_path = 'data/{0}/e1rel_to_e2_train.json'.format(dataset_name)\n",
    "    dev_ranking_path = 'data/{0}/e1rel_to_e2_ranking_dev.json'.format(dataset_name)\n",
    "    test_ranking_path = 'data/{0}/e1rel_to_e2_ranking_test.json'.format(dataset_name)\n",
    "\n",
    "    keys2keys = {}\n",
    "    keys2keys['e1'] = 'e1' # entities\n",
    "    keys2keys['rel'] = 'rel' # relations\n",
    "    keys2keys['rel_eval'] = 'rel' # relations\n",
    "    keys2keys['e2'] = 'e1' # entities\n",
    "    keys2keys['e2_multi1'] = 'e1' # entity\n",
    "    keys2keys['e2_multi2'] = 'e1' # entity\n",
    "    input_keys = ['e1', 'rel', 'rel_eval', 'e2', 'e2_multi1', 'e2_multi2']\n",
    "    d = DatasetStreamer(input_keys)\n",
    "    d.add_stream_processor(JsonLoaderProcessors())\n",
    "    d.add_stream_processor(DictKey2ListMapper(input_keys))\n",
    "\n",
    "    # process full vocabulary and save it to disk\n",
    "    d.set_path(full_path)\n",
    "    p = Pipeline(args.data, delete_data, keys=input_keys, skip_transformation=True)\n",
    "    p.add_sent_processor(ToLower())\n",
    "    p.add_sent_processor(CustomTokenizer(lambda x: x.split(' ')),keys=['e2_multi1', 'e2_multi2'])\n",
    "    p.add_token_processor(AddToVocab())\n",
    "    p.execute(d)\n",
    "    p.save_vocabs()\n",
    "\n",
    "\n",
    "    # process train, dev and test sets and save them to hdf5\n",
    "    p.skip_transformation = False\n",
    "    for path, name in zip([train_path, dev_ranking_path, test_ranking_path], ['train', 'dev_ranking', 'test_ranking']):\n",
    "        d.set_path(path)\n",
    "        p.clear_processors()\n",
    "        p.add_sent_processor(ToLower())\n",
    "        p.add_sent_processor(CustomTokenizer(lambda x: x.split(' ')),keys=['e2_multi1', 'e2_multi2'])\n",
    "        p.add_post_processor(ConvertTokenToIdx(keys2keys=keys2keys), keys=['e1', 'rel', 'rel_eval', 'e2', 'e2_multi1', 'e2_multi2'])\n",
    "        p.add_post_processor(StreamToHDF5(name, samples_per_file=1000, keys=input_keys))\n",
    "        p.execute(d)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 4,
   "id": "756a7067",
   "metadata": {},
   "outputs": [],
   "source": [
    "def main(args, model_path):\n",
    "    if args.preprocess:\n",
    "        preprocess(args.data, delete_data=True)\n",
    "    input_keys = ['e1', 'rel', 'rel_eval', 'e2', 'e2_multi1', 'e2_multi2']\n",
    "    p = Pipeline(args.data, keys=input_keys)\n",
    "    p.load_vocabs()\n",
    "    vocab = p.state['vocab']\n",
    "\n",
    "    train_batcher = StreamBatcher(args.data, 'train', args.batch_size, randomize=True, keys=input_keys, loader_threads=args.loader_threads)\n",
    "    dev_rank_batcher = StreamBatcher(args.data, 'dev_ranking', args.test_batch_size, randomize=False, loader_threads=args.loader_threads, keys=input_keys)\n",
    "    test_rank_batcher = StreamBatcher(args.data, 'test_ranking', args.test_batch_size, randomize=False, loader_threads=args.loader_threads, keys=input_keys)\n",
    "\n",
    "\n",
    "    data = []\n",
    "    rows = []\n",
    "    columns = []\n",
    "    num_entities = vocab['e1'].num_token\n",
    "    num_relations = vocab['rel'].num_token\n",
    "\n",
    "    if args.preprocess:\n",
    "        for i, str2var in enumerate(train_batcher):\n",
    "            print(\"batch number:\", i)\n",
    "            for j in range(str2var['e1'].shape[0]):\n",
    "                for k in range(str2var['e2_multi1'][j].shape[0]):\n",
    "                    if str2var['e2_multi1'][j][k] != 0:\n",
    "                        data.append(str2var['rel'][j].cpu().tolist()[0])\n",
    "                        rows.append(str2var['e1'][j].cpu().tolist()[0])\n",
    "                        columns.append(str2var['e2_multi1'][j][k].cpu().tolist())\n",
    "                    else:\n",
    "                        break\n",
    "\n",
    "        from graph4nlp.pytorch.data.data import GraphData, to_batch\n",
    "        \n",
    "        KG_graph = GraphData()\n",
    "        KG_graph.add_nodes(num_entities)\n",
    "        for e1, rel, e2 in zip(rows, data, columns):\n",
    "            KG_graph.add_edge(e1, e2)\n",
    "            eid = KG_graph.edge_ids(e1, e2)[0]\n",
    "            KG_graph.edge_attributes[eid]['token'] = rel\n",
    "\n",
    "        torch.save(KG_graph, '{}/processed/KG_graph.pt'.format(args.data))\n",
    "        return\n",
    "\n",
    "\n",
    "    if args.model is None:\n",
    "        model = ConvE(args, vocab['e1'].num_token, vocab['rel'].num_token)\n",
    "    elif args.model == 'conve':\n",
    "        model = ConvE(args, vocab['e1'].num_token, vocab['rel'].num_token)\n",
    "    elif args.model == 'distmult':\n",
    "        model = Distmult(args, vocab['e1'].num_token, vocab['rel'].num_token)\n",
    "    elif args.model == 'complex':\n",
    "        model = Complex(args, vocab['e1'].num_token, vocab['rel'].num_token)\n",
    "    elif args.model == 'ggnn_distmult':\n",
    "        model = GGNNDistMult(args, vocab['e1'].num_token, vocab['rel'].num_token)\n",
    "    elif args.model == 'gcn_distmult':\n",
    "        model = GCNDistMult(args, vocab['e1'].num_token, vocab['rel'].num_token)\n",
    "    elif args.model == 'gcn_complex':\n",
    "        model = GCNComplex(args, vocab['e1'].num_token, vocab['rel'].num_token)\n",
    "    else:\n",
    "        raise Exception(\"Unknown model!\")\n",
    "\n",
    "    if args.model in ['ggnn_distmult', 'gcn_distmult', 'gcn_complex']:\n",
    "        graph_path = '{}/processed/KG_graph.pt'.format(args.data)\n",
    "        KG_graph = torch.load(graph_path)\n",
    "        if Config.cuda:\n",
    "            KG_graph = KG_graph.to('cuda')\n",
    "    else:\n",
    "        KG_graph = None\n",
    "\n",
    "    train_batcher.at_batch_prepared_observers.insert(1,TargetIdx2MultiTarget(num_entities, 'e2_multi1', 'e2_multi1_binary'))\n",
    "\n",
    "    eta = ETAHook('train', print_every_x_batches=args.log_interval)\n",
    "    train_batcher.subscribe_to_events(eta)\n",
    "    train_batcher.subscribe_to_start_of_epoch_event(eta)\n",
    "    train_batcher.subscribe_to_events(LossHook('train', print_every_x_batches=args.log_interval))\n",
    "    if Config.cuda:\n",
    "        model.cuda()\n",
    "    if args.resume:\n",
    "        model_params = torch.load(model_path)\n",
    "        print(model)\n",
    "        total_param_size = []\n",
    "        params = [(key, value.size(), value.numel()) for key, value in model_params.items()]\n",
    "        for key, size, count in params:\n",
    "            total_param_size.append(count)\n",
    "            print(key, size, count)\n",
    "        print(np.array(total_param_size).sum())\n",
    "        model.load_state_dict(model_params)\n",
    "        model.eval()\n",
    "        ranking_and_hits(model, test_rank_batcher, vocab, 'test_evaluation', kg_graph=KG_graph)\n",
    "        ranking_and_hits(model, dev_rank_batcher, vocab, 'dev_evaluation', kg_graph=KG_graph)\n",
    "    else:\n",
    "        model.init()\n",
    "\n",
    "    total_param_size = []\n",
    "    params = [value.numel() for value in model.parameters()]\n",
    "    print(params)\n",
    "    print(np.sum(params))\n",
    "\n",
    "    best_mrr = 0\n",
    "\n",
    "    opt = torch.optim.Adam(model.parameters(), lr=args.lr, weight_decay=args.l2)\n",
    "    for epoch in range(args.epochs):\n",
    "        model.train()\n",
    "        for i, str2var in enumerate(train_batcher):\n",
    "            opt.zero_grad()\n",
    "            e1 = str2var['e1']\n",
    "            rel = str2var['rel']\n",
    "            e2_multi = str2var['e2_multi1_binary'].float()\n",
    "            # label smoothing\n",
    "            e2_multi = ((1.0-args.label_smoothing)*e2_multi) + (1.0/e2_multi.size(1))\n",
    "\n",
    "            pred = model.forward(e1, rel, KG_graph)\n",
    "            loss = model.loss(pred, e2_multi)\n",
    "            loss.backward()\n",
    "            opt.step()\n",
    "\n",
    "            train_batcher.state.loss = loss.cpu()\n",
    "\n",
    "        model.eval()\n",
    "        with torch.no_grad():\n",
    "            if epoch % 2 == 0 and epoch > 0:\n",
    "                dev_mrr = ranking_and_hits(model, dev_rank_batcher, vocab, 'dev_evaluation', kg_graph=KG_graph)\n",
    "                if dev_mrr > best_mrr:\n",
    "                    best_mrr = dev_mrr\n",
    "                    print('saving best model to {0}'.format(model_path))\n",
    "                    torch.save(model.state_dict(), model_path)\n",
    "            if epoch % 2 == 0:\n",
    "                if epoch > 0:\n",
    "                    ranking_and_hits(model, test_rank_batcher, vocab, 'test_evaluation', kg_graph=KG_graph)"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "7feed43c",
   "metadata": {},
   "source": [
    "### Config Setup"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 5,
   "id": "37083908",
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/plain": [
       "_StoreAction(option_strings=['--kernel_size'], dest='kernel_size', nargs=None, const=None, default=5, type=<class 'int'>, choices=None, help='The side of the hidden layer. The required size changes with the size of the embeddings. Default: 9728 (embedding size 200).', metavar=None)"
      ]
     },
     "execution_count": 5,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "parser = argparse.ArgumentParser(description='Link prediction for knowledge graphs')\n",
    "parser.add_argument('--batch-size', type=int, default=128, help='input batch size for training (default: 128)')\n",
    "parser.add_argument('--test-batch-size', type=int, default=128, help='input batch size for testing/validation (default: 128)')\n",
    "parser.add_argument('--epochs', type=int, default=1000, help='number of epochs to train (default: 1000)')\n",
    "parser.add_argument('--lr', type=float, default=0.003, help='learning rate (default: 0.003)')\n",
    "parser.add_argument('--seed', type=int, default=1234, metavar='S', help='random seed (default: 17)')\n",
    "parser.add_argument('--log-interval', type=int, default=100, help='how many batches to wait before logging training status')\n",
    "parser.add_argument('--data', type=str, default='kinship', help='Dataset to use: {FB15k-237, YAGO3-10, WN18RR, umls, nations, kinship}, default: FB15k-237')\n",
    "parser.add_argument('--l2', type=float, default=0.0, help='Weight decay value to use in the optimizer. Default: 0.0')\n",
    "parser.add_argument('--model', type=str, default='ggnn_distmult', help='Choose from: {conve, distmult, complex}')\n",
    "parser.add_argument('--direction_option', type=str, default='undirected', help='Choose from: {undirected, bi_sep, bi_fuse}')\n",
    "parser.add_argument('--embedding-dim', type=int, default=200, help='The embedding dimension (1D). Default: 200')\n",
    "parser.add_argument('--embedding-shape1', type=int, default=20, help='The first dimension of the reshaped 2D embedding. The second dimension is infered. Default: 20')\n",
    "parser.add_argument('--hidden-drop', type=float, default=0.25, help='Dropout for the hidden layer. Default: 0.3.')\n",
    "parser.add_argument('--input-drop', type=float, default=0.2, help='Dropout for the input embeddings. Default: 0.2.')\n",
    "parser.add_argument('--feat-drop', type=float, default=0.2, help='Dropout for the convolutional features. Default: 0.2.')\n",
    "parser.add_argument('--lr-decay', type=float, default=0.995, help='Decay the learning rate by this factor every epoch. Default: 0.995')\n",
    "parser.add_argument('--loader-threads', type=int, default=4, help='How many loader threads to use for the batch loaders. Default: 4')\n",
    "parser.add_argument('--preprocess', action='store_true', help='Preprocess the dataset. Needs to be executed only once. Default: 4')\n",
    "parser.add_argument('--resume', action='store_true', help='Resume a model.')\n",
    "parser.add_argument('--use-bias', action='store_true', help='Use a bias in the convolutional layer. Default: True')\n",
    "parser.add_argument('--label-smoothing', type=float, default=0.1, help='Label smoothing value to use. Default: 0.1')\n",
    "parser.add_argument('--hidden-size', type=int, default=9728, help='The side of the hidden layer. The required size changes with the size of the embeddings. Default: 9728 (embedding size 200).')\n",
    "\n",
    "parser.add_argument('--channels', type=int, default=200, help='The side of the hidden layer. The required size changes with the size of the embeddings. Default: 9728 (embedding size 200).')\n",
    "parser.add_argument('--kernel_size', type=int, default=5, help='The side of the hidden layer. The required size changes with the size of the embeddings. Default: 9728 (embedding size 200).')"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "ea2805c4",
   "metadata": {},
   "source": [
    "### If you run the task for the first time, run with:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 6,
   "id": "bd54a377",
   "metadata": {},
   "outputs": [],
   "source": [
    "args = parser.parse_args(args=['--data', 'kinship', '--model', 'ggnn_distmult', '--preprocess'])"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 7,
   "id": "8f7de8be",
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/plain": [
       "<torch._C.Generator at 0x7fca88209870>"
      ]
     },
     "execution_count": 7,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "# parse console parameters and set global variables\n",
    "Config.backend = 'pytorch'\n",
    "Config.cuda = False\n",
    "Config.embedding_dim = args.embedding_dim\n",
    "\n",
    "model_name = '{2}_{0}_{1}'.format(args.input_drop, args.hidden_drop, args.model)\n",
    "model_path = 'saved_models/{0}_{1}.model'.format(args.data, model_name)\n",
    "\n",
    "torch.manual_seed(args.seed)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 8,
   "id": "a16d15f6",
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/plain": [
       "True"
      ]
     },
     "execution_count": 8,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "args.preprocess"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 9,
   "id": "44f0a58d",
   "metadata": {},
   "outputs": [],
   "source": [
    "import warnings\n",
    "warnings.filterwarnings('ignore')"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "9ed30dc8",
   "metadata": {},
   "source": [
    "### After preprocess the kinship data, then run:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 10,
   "id": "f305c737",
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 01:25:45.025464 (WARNING): delete_all_previous_data=True! Deleting all folder contents of folder /Users/hugo/.data/kinship!\n",
      "2021-08-11 01:25:45.070188 (INFO): Recreating path: /Users/hugo/.data/kinship\n",
      "2021-08-11 01:25:45.193284 (INFO): Time taken for 10000 samples for input type rel for processor AddToVocab: 0.02 seconds\n",
      "2021-08-11 01:25:45.372957 (INFO): Time taken for 10000 samples for input type e2 for processor ToLower: 0.01 seconds\n",
      "2021-08-11 01:25:45.373351 (INFO): Time taken for 10000 samples for input type e2 for processor SaveLengthsToState: 0.04 seconds\n",
      "2021-08-11 01:25:45.729156 (INFO): Time taken for 10000 samples for input type e2_multi2 for processor CustomTokenizer: 0.02 seconds\n",
      "2021-08-11 01:25:45.817601 (INFO): Saving vocab to: /Users/hugo/.data/kinship/vocab\n",
      "2021-08-11 01:25:45.818879 (INFO): Saving vocab to: /Users/hugo/.data/kinship/vocab_e1\n",
      "2021-08-11 01:25:45.819535 (INFO): Saving vocab to: /Users/hugo/.data/kinship/vocab_rel\n",
      "2021-08-11 01:25:45.820164 (INFO): Saving vocab to: /Users/hugo/.data/kinship/vocab_rel_eval\n",
      "2021-08-11 01:25:45.820701 (INFO): Saving vocab to: /Users/hugo/.data/kinship/vocab_e2\n",
      "2021-08-11 01:25:45.821306 (INFO): Saving vocab to: /Users/hugo/.data/kinship/vocab_e2_multi1\n",
      "2021-08-11 01:25:45.821996 (INFO): Saving vocab to: /Users/hugo/.data/kinship/vocab_e2_multi2\n",
      "2021-08-11 01:25:45.993193 (INFO): Time taken for 10000 samples for input type e2 for processor ToLower: 0.01 seconds\n",
      "2021-08-11 01:25:45.993510 (INFO): Time taken for 10000 samples for input type e2 for processor SaveLengthsToState: 0.04 seconds\n",
      "2021-08-11 01:25:46.451877 (INFO): Time taken for 10000 samples for input type e2 for processor ConvertTokenToIdx: 0.04 seconds\n",
      "2021-08-11 01:25:46.452114 (INFO): Time taken for 10000 samples for input type e2 for processor StreamToHDF5: 0.11 seconds\n",
      "2021-08-11 01:25:46.486225 (INFO): Time taken for 10000 samples for input type e2_multi2 for processor CustomTokenizer: 0.02 seconds\n",
      "2021-08-11 01:25:47.472816 (WARNING): Pipeline path /Users/hugo/.data/kinship already exist. This pipeline may overwrite data in this path!\n",
      "2021-08-11 01:25:47.474959 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab\n",
      "2021-08-11 01:25:47.475738 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab_e1\n",
      "2021-08-11 01:25:47.476367 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab_rel\n",
      "2021-08-11 01:25:47.477049 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab_rel_eval\n",
      "2021-08-11 01:25:47.477684 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab_e2\n",
      "2021-08-11 01:25:47.478374 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab_e2_multi1\n",
      "2021-08-11 01:25:47.479019 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab_e2_multi2\n",
      "batch number: 0\n",
      "batch number: 1\n",
      "batch number: 2\n",
      "batch number: 3\n",
      "batch number: 4\n",
      "batch number: 5\n",
      "batch number: 6\n",
      "batch number: 7\n",
      "batch number: 8\n",
      "batch number: 9\n",
      "batch number: 10\n",
      "batch number: 11\n",
      "batch number: 12\n",
      "batch number: 13\n",
      "batch number: 14\n",
      "batch number: 15\n",
      "batch number: 16\n",
      "batch number: 17\n",
      "batch number: 18\n",
      "batch number: 19\n",
      "batch number: 20\n",
      "batch number: 21\n",
      "batch number: 22\n",
      "batch number: 23\n"
     ]
    }
   ],
   "source": [
    "main(args, model_path)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 11,
   "id": "2b6544c0",
   "metadata": {},
   "outputs": [],
   "source": [
    "args = parser.parse_args(args=['--data', 'kinship', '--model', 'ggnn_distmult'])"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "id": "36b28f5a",
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 01:26:36.991522 (WARNING): Pipeline path /Users/hugo/.data/kinship already exist. This pipeline may overwrite data in this path!\n",
      "2021-08-11 01:26:36.992632 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab\n",
      "2021-08-11 01:26:36.993748 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab_e1\n",
      "2021-08-11 01:26:37.002026 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab_rel\n",
      "2021-08-11 01:26:37.003720 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab_rel_eval\n",
      "2021-08-11 01:26:37.005099 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab_e2\n",
      "2021-08-11 01:26:37.006257 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab_e2_multi1\n",
      "2021-08-11 01:26:37.012940 (INFO): Loading vocab from: /Users/hugo/.data/kinship/vocab_e2_multi2\n",
      "[21200, 10400, 40000, 200, 120000, 120000, 600, 600]\n",
      "313000\n",
      "2021-08-11 01:26:58.652849 (INFO): Total epoch time: 0:00:16\n",
      "2021-08-11 01:26:58.695876 (INFO): \n",
      "\n",
      "2021-08-11 01:26:58.697975 (INFO): ########################################\n",
      "2021-08-11 01:26:58.698057 (INFO):           COMPLETED EPOCH: 1                              \n",
      "2021-08-11 01:26:58.698099 (INFO): train Loss: 0.69271\t99% CI: (0.6925, 0.69291), n=23\n",
      "2021-08-11 01:26:58.698490 (INFO): ########################################\n",
      "2021-08-11 01:26:58.698549 (INFO): \n",
      "\n",
      "2021-08-11 01:27:11.447954 (INFO): Total epoch time: 0:00:12\n",
      "2021-08-11 01:27:11.461157 (INFO): \n",
      "\n",
      "2021-08-11 01:27:11.461545 (INFO): ########################################\n",
      "2021-08-11 01:27:11.462014 (INFO):           COMPLETED EPOCH: 2                              \n",
      "2021-08-11 01:27:11.463937 (INFO): train Loss: 0.68494\t99% CI: (0.68215, 0.68773), n=23\n",
      "2021-08-11 01:27:11.464004 (INFO): ########################################\n",
      "2021-08-11 01:27:11.464045 (INFO): \n",
      "\n",
      "2021-08-11 01:27:22.046500 (INFO): Total epoch time: 0:00:10\n",
      "2021-08-11 01:27:22.047701 (INFO): \n",
      "\n",
      "2021-08-11 01:27:22.047785 (INFO): ########################################\n",
      "2021-08-11 01:27:22.047834 (INFO):           COMPLETED EPOCH: 3                              \n",
      "2021-08-11 01:27:22.047874 (INFO): train Loss: 0.60822\t99% CI: (0.58622, 0.63023), n=23\n",
      "2021-08-11 01:27:22.048503 (INFO): ########################################\n",
      "2021-08-11 01:27:22.048636 (INFO): \n",
      "\n",
      "2021-08-11 01:27:22.049049 (INFO): \n",
      "2021-08-11 01:27:22.049134 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:27:22.049179 (INFO): dev_evaluation\n",
      "2021-08-11 01:27:22.049727 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:27:22.050344 (INFO): \n",
      "2021-08-11 01:27:56.674426 (INFO): Hits left @1: 0.0166015625\n",
      "2021-08-11 01:27:56.675057 (INFO): Hits right @1: 0.0068359375\n",
      "2021-08-11 01:27:56.675414 (INFO): Hits @1: 0.01171875\n",
      "2021-08-11 01:27:56.675620 (INFO): Hits left @2: 0.03125\n",
      "2021-08-11 01:27:56.675804 (INFO): Hits right @2: 0.0146484375\n",
      "2021-08-11 01:27:56.676921 (INFO): Hits @2: 0.02294921875\n",
      "2021-08-11 01:27:56.677131 (INFO): Hits left @3: 0.0380859375\n",
      "2021-08-11 01:27:56.677702 (INFO): Hits right @3: 0.0224609375\n",
      "2021-08-11 01:27:56.677984 (INFO): Hits @3: 0.0302734375\n",
      "2021-08-11 01:27:56.678170 (INFO): Hits left @4: 0.0458984375\n",
      "2021-08-11 01:27:56.678350 (INFO): Hits right @4: 0.0322265625\n",
      "2021-08-11 01:27:56.678605 (INFO): Hits @4: 0.0390625\n",
      "2021-08-11 01:27:56.679193 (INFO): Hits left @5: 0.0556640625\n",
      "2021-08-11 01:27:56.679387 (INFO): Hits right @5: 0.0478515625\n",
      "2021-08-11 01:27:56.679649 (INFO): Hits @5: 0.0517578125\n",
      "2021-08-11 01:27:56.680188 (INFO): Hits left @6: 0.07421875\n",
      "2021-08-11 01:27:56.680371 (INFO): Hits right @6: 0.0576171875\n",
      "2021-08-11 01:27:56.680629 (INFO): Hits @6: 0.06591796875\n",
      "2021-08-11 01:27:56.680799 (INFO): Hits left @7: 0.087890625\n",
      "2021-08-11 01:27:56.680967 (INFO): Hits right @7: 0.0673828125\n",
      "2021-08-11 01:27:56.681217 (INFO): Hits @7: 0.07763671875\n",
      "2021-08-11 01:27:56.681386 (INFO): Hits left @8: 0.0986328125\n",
      "2021-08-11 01:27:56.681985 (INFO): Hits right @8: 0.0771484375\n",
      "2021-08-11 01:27:56.682249 (INFO): Hits @8: 0.087890625\n",
      "2021-08-11 01:27:56.682428 (INFO): Hits left @9: 0.1123046875\n",
      "2021-08-11 01:27:56.682600 (INFO): Hits right @9: 0.091796875\n",
      "2021-08-11 01:27:56.682859 (INFO): Hits @9: 0.10205078125\n",
      "2021-08-11 01:27:56.705239 (INFO): Hits left @10: 0.1240234375\n",
      "2021-08-11 01:27:56.705812 (INFO): Hits right @10: 0.10546875\n",
      "2021-08-11 01:27:56.706096 (INFO): Hits @10: 0.11474609375\n",
      "2021-08-11 01:27:56.706272 (INFO): Mean rank left: 46.1318359375\n",
      "2021-08-11 01:27:56.706437 (INFO): Mean rank right: 45.791015625\n",
      "2021-08-11 01:27:56.706667 (INFO): Mean rank: 45.96142578125\n",
      "2021-08-11 01:27:56.706931 (INFO): Mean reciprocal rank left: 0.06265919451049534\n",
      "2021-08-11 01:27:56.707292 (INFO): Mean reciprocal rank right: 0.0506665653922437\n",
      "2021-08-11 01:27:56.708198 (INFO): Mean reciprocal rank: 0.056662879951369524\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 01:27:56.813981 (INFO): \n",
      "2021-08-11 01:27:56.848223 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:27:56.848805 (INFO): test_evaluation\n",
      "2021-08-11 01:27:56.848868 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:27:56.848911 (INFO): \n",
      "2021-08-11 01:28:30.861161 (INFO): Hits left @1: 0.013671875\n",
      "2021-08-11 01:28:30.862122 (INFO): Hits right @1: 0.01171875\n",
      "2021-08-11 01:28:30.862408 (INFO): Hits @1: 0.0126953125\n",
      "2021-08-11 01:28:30.862589 (INFO): Hits left @2: 0.0234375\n",
      "2021-08-11 01:28:30.862857 (INFO): Hits right @2: 0.0283203125\n",
      "2021-08-11 01:28:30.863152 (INFO): Hits @2: 0.02587890625\n",
      "2021-08-11 01:28:30.863334 (INFO): Hits left @3: 0.03125\n",
      "2021-08-11 01:28:30.863968 (INFO): Hits right @3: 0.041015625\n",
      "2021-08-11 01:28:30.864659 (INFO): Hits @3: 0.0361328125\n",
      "2021-08-11 01:28:30.864848 (INFO): Hits left @4: 0.0419921875\n",
      "2021-08-11 01:28:30.865025 (INFO): Hits right @4: 0.048828125\n",
      "2021-08-11 01:28:30.865282 (INFO): Hits @4: 0.04541015625\n",
      "2021-08-11 01:28:30.866179 (INFO): Hits left @5: 0.052734375\n",
      "2021-08-11 01:28:30.866374 (INFO): Hits right @5: 0.0634765625\n",
      "2021-08-11 01:28:30.866655 (INFO): Hits @5: 0.05810546875\n",
      "2021-08-11 01:28:30.867139 (INFO): Hits left @6: 0.068359375\n",
      "2021-08-11 01:28:30.867321 (INFO): Hits right @6: 0.07421875\n",
      "2021-08-11 01:28:30.867578 (INFO): Hits @6: 0.0712890625\n",
      "2021-08-11 01:28:30.867751 (INFO): Hits left @7: 0.0869140625\n",
      "2021-08-11 01:28:30.867919 (INFO): Hits right @7: 0.0869140625\n",
      "2021-08-11 01:28:30.868170 (INFO): Hits @7: 0.0869140625\n",
      "2021-08-11 01:28:30.868815 (INFO): Hits left @8: 0.0947265625\n",
      "2021-08-11 01:28:30.869008 (INFO): Hits right @8: 0.091796875\n",
      "2021-08-11 01:28:30.869270 (INFO): Hits @8: 0.09326171875\n",
      "2021-08-11 01:28:30.869445 (INFO): Hits left @9: 0.109375\n",
      "2021-08-11 01:28:30.869622 (INFO): Hits right @9: 0.1025390625\n",
      "2021-08-11 01:28:30.870166 (INFO): Hits @9: 0.10595703125\n",
      "2021-08-11 01:28:30.870342 (INFO): Hits left @10: 0.119140625\n",
      "2021-08-11 01:28:30.870510 (INFO): Hits right @10: 0.1171875\n",
      "2021-08-11 01:28:30.870760 (INFO): Hits @10: 0.1181640625\n",
      "2021-08-11 01:28:30.870936 (INFO): Mean rank left: 45.7802734375\n",
      "2021-08-11 01:28:30.871357 (INFO): Mean rank right: 45.384765625\n",
      "2021-08-11 01:28:30.871580 (INFO): Mean rank: 45.58251953125\n",
      "2021-08-11 01:28:30.872028 (INFO): Mean reciprocal rank left: 0.05861384486778151\n",
      "2021-08-11 01:28:30.872459 (INFO): Mean reciprocal rank right: 0.059880245887321056\n",
      "2021-08-11 01:28:30.872784 (INFO): Mean reciprocal rank: 0.05924704537755128\n",
      "2021-08-11 01:28:43.487050 (INFO): Total epoch time: 0:00:12\n",
      "2021-08-11 01:28:43.505246 (INFO): \n",
      "\n",
      "2021-08-11 01:28:43.505391 (INFO): ########################################\n",
      "2021-08-11 01:28:43.505942 (INFO):           COMPLETED EPOCH: 4                              \n",
      "2021-08-11 01:28:43.506003 (INFO): train Loss: 0.35505\t99% CI: (0.31689, 0.39321), n=23\n",
      "2021-08-11 01:28:43.506047 (INFO): ########################################\n",
      "2021-08-11 01:28:43.506085 (INFO): \n",
      "\n",
      "2021-08-11 01:28:55.969381 (INFO): Total epoch time: 0:00:12\n",
      "2021-08-11 01:28:56.108921 (INFO): \n",
      "\n",
      "2021-08-11 01:28:56.157250 (INFO): ########################################\n",
      "2021-08-11 01:28:56.157335 (INFO):           COMPLETED EPOCH: 5                              \n",
      "2021-08-11 01:28:56.158224 (INFO): train Loss: 0.21113\t99% CI: (0.19255, 0.22972), n=23\n",
      "2021-08-11 01:28:56.158761 (INFO): ########################################\n",
      "2021-08-11 01:28:56.158823 (INFO): \n",
      "\n",
      "2021-08-11 01:28:56.159003 (INFO): \n",
      "2021-08-11 01:28:56.159052 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:28:56.159396 (INFO): dev_evaluation\n",
      "2021-08-11 01:28:56.159436 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:28:56.159471 (INFO): \n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 01:29:27.287915 (INFO): Hits left @1: 0.0322265625\n",
      "2021-08-11 01:29:27.288484 (INFO): Hits right @1: 0.029296875\n",
      "2021-08-11 01:29:27.288765 (INFO): Hits @1: 0.03076171875\n",
      "2021-08-11 01:29:27.288944 (INFO): Hits left @2: 0.0625\n",
      "2021-08-11 01:29:27.289116 (INFO): Hits right @2: 0.0576171875\n",
      "2021-08-11 01:29:27.289372 (INFO): Hits @2: 0.06005859375\n",
      "2021-08-11 01:29:27.290036 (INFO): Hits left @3: 0.0947265625\n",
      "2021-08-11 01:29:27.290208 (INFO): Hits right @3: 0.080078125\n",
      "2021-08-11 01:29:27.290460 (INFO): Hits @3: 0.08740234375\n",
      "2021-08-11 01:29:27.290628 (INFO): Hits left @4: 0.126953125\n",
      "2021-08-11 01:29:27.290795 (INFO): Hits right @4: 0.1025390625\n",
      "2021-08-11 01:29:27.291381 (INFO): Hits @4: 0.11474609375\n",
      "2021-08-11 01:29:27.291551 (INFO): Hits left @5: 0.154296875\n",
      "2021-08-11 01:29:27.291719 (INFO): Hits right @5: 0.1328125\n",
      "2021-08-11 01:29:27.291970 (INFO): Hits @5: 0.1435546875\n",
      "2021-08-11 01:29:27.292137 (INFO): Hits left @6: 0.1806640625\n",
      "2021-08-11 01:29:27.292691 (INFO): Hits right @6: 0.1650390625\n",
      "2021-08-11 01:29:27.292975 (INFO): Hits @6: 0.1728515625\n",
      "2021-08-11 01:29:27.293158 (INFO): Hits left @7: 0.2041015625\n",
      "2021-08-11 01:29:27.293334 (INFO): Hits right @7: 0.1826171875\n",
      "2021-08-11 01:29:27.293589 (INFO): Hits @7: 0.193359375\n",
      "2021-08-11 01:29:27.294058 (INFO): Hits left @8: 0.2255859375\n",
      "2021-08-11 01:29:27.294229 (INFO): Hits right @8: 0.2109375\n",
      "2021-08-11 01:29:27.294482 (INFO): Hits @8: 0.21826171875\n",
      "2021-08-11 01:29:27.294649 (INFO): Hits left @9: 0.248046875\n",
      "2021-08-11 01:29:27.294818 (INFO): Hits right @9: 0.2373046875\n",
      "2021-08-11 01:29:27.295067 (INFO): Hits @9: 0.24267578125\n",
      "2021-08-11 01:29:27.295267 (INFO): Hits left @10: 0.271484375\n",
      "2021-08-11 01:29:27.295436 (INFO): Hits right @10: 0.2587890625\n",
      "2021-08-11 01:29:27.295689 (INFO): Hits @10: 0.26513671875\n",
      "2021-08-11 01:29:27.295868 (INFO): Mean rank left: 31.265625\n",
      "2021-08-11 01:29:27.296031 (INFO): Mean rank right: 30.67578125\n",
      "2021-08-11 01:29:27.296256 (INFO): Mean rank: 30.970703125\n",
      "2021-08-11 01:29:27.296583 (INFO): Mean reciprocal rank left: 0.11183263034374734\n",
      "2021-08-11 01:29:27.297813 (INFO): Mean reciprocal rank right: 0.10544019820735455\n",
      "2021-08-11 01:29:27.298170 (INFO): Mean reciprocal rank: 0.10863641427555094\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 01:29:27.308473 (INFO): \n",
      "2021-08-11 01:29:27.309032 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:29:27.309097 (INFO): test_evaluation\n",
      "2021-08-11 01:29:27.309138 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:29:27.309180 (INFO): \n",
      "2021-08-11 01:29:53.781488 (INFO): Hits left @1: 0.0400390625\n",
      "2021-08-11 01:29:53.809957 (INFO): Hits right @1: 0.037109375\n",
      "2021-08-11 01:29:53.810272 (INFO): Hits @1: 0.03857421875\n",
      "2021-08-11 01:29:53.810535 (INFO): Hits left @2: 0.064453125\n",
      "2021-08-11 01:29:53.811096 (INFO): Hits right @2: 0.0634765625\n",
      "2021-08-11 01:29:53.818867 (INFO): Hits @2: 0.06396484375\n",
      "2021-08-11 01:29:53.819481 (INFO): Hits left @3: 0.0869140625\n",
      "2021-08-11 01:29:53.819691 (INFO): Hits right @3: 0.08984375\n",
      "2021-08-11 01:29:53.819965 (INFO): Hits @3: 0.08837890625\n",
      "2021-08-11 01:29:53.820145 (INFO): Hits left @4: 0.1171875\n",
      "2021-08-11 01:29:53.820320 (INFO): Hits right @4: 0.1162109375\n",
      "2021-08-11 01:29:53.821258 (INFO): Hits @4: 0.11669921875\n",
      "2021-08-11 01:29:53.821460 (INFO): Hits left @5: 0.1357421875\n",
      "2021-08-11 01:29:53.821643 (INFO): Hits right @5: 0.1435546875\n",
      "2021-08-11 01:29:53.822662 (INFO): Hits @5: 0.1396484375\n",
      "2021-08-11 01:29:53.822856 (INFO): Hits left @6: 0.1591796875\n",
      "2021-08-11 01:29:53.823093 (INFO): Hits right @6: 0.1640625\n",
      "2021-08-11 01:29:53.845574 (INFO): Hits @6: 0.16162109375\n",
      "2021-08-11 01:29:53.852420 (INFO): Hits left @7: 0.1875\n",
      "2021-08-11 01:29:53.852639 (INFO): Hits right @7: 0.1845703125\n",
      "2021-08-11 01:29:53.882262 (INFO): Hits @7: 0.18603515625\n",
      "2021-08-11 01:29:53.893787 (INFO): Hits left @8: 0.2041015625\n",
      "2021-08-11 01:29:53.894015 (INFO): Hits right @8: 0.2001953125\n",
      "2021-08-11 01:29:53.894290 (INFO): Hits @8: 0.2021484375\n",
      "2021-08-11 01:29:53.894469 (INFO): Hits left @9: 0.22265625\n",
      "2021-08-11 01:29:53.894643 (INFO): Hits right @9: 0.228515625\n",
      "2021-08-11 01:29:53.894902 (INFO): Hits @9: 0.2255859375\n",
      "2021-08-11 01:29:53.895480 (INFO): Hits left @10: 0.2451171875\n",
      "2021-08-11 01:29:53.895673 (INFO): Hits right @10: 0.251953125\n",
      "2021-08-11 01:29:53.895937 (INFO): Hits @10: 0.24853515625\n",
      "2021-08-11 01:29:53.896145 (INFO): Mean rank left: 31.5751953125\n",
      "2021-08-11 01:29:53.896317 (INFO): Mean rank right: 30.083984375\n",
      "2021-08-11 01:29:53.896615 (INFO): Mean rank: 30.82958984375\n",
      "2021-08-11 01:29:53.896889 (INFO): Mean reciprocal rank left: 0.11119397952751081\n",
      "2021-08-11 01:29:53.897424 (INFO): Mean reciprocal rank right: 0.11211763555159282\n",
      "2021-08-11 01:29:53.898092 (INFO): Mean reciprocal rank: 0.11165580753955182\n",
      "2021-08-11 01:30:07.302014 (INFO): Total epoch time: 0:00:13\n",
      "2021-08-11 01:30:07.302918 (INFO): \n",
      "\n",
      "2021-08-11 01:30:07.302993 (INFO): ########################################\n",
      "2021-08-11 01:30:07.303047 (INFO):           COMPLETED EPOCH: 6                              \n",
      "2021-08-11 01:30:07.303089 (INFO): train Loss: 0.2062\t99% CI: (0.17925, 0.23315), n=23\n",
      "2021-08-11 01:30:07.303125 (INFO): ########################################\n",
      "2021-08-11 01:30:07.304249 (INFO): \n",
      "\n",
      "2021-08-11 01:30:18.957323 (INFO): Total epoch time: 0:00:11\n",
      "2021-08-11 01:30:18.958191 (INFO): \n",
      "\n",
      "2021-08-11 01:30:18.958262 (INFO): ########################################\n",
      "2021-08-11 01:30:18.958307 (INFO):           COMPLETED EPOCH: 7                              \n",
      "2021-08-11 01:30:18.958346 (INFO): train Loss: 0.18975\t99% CI: (0.16455, 0.21496), n=23\n",
      "2021-08-11 01:30:18.958383 (INFO): ########################################\n",
      "2021-08-11 01:30:18.958418 (INFO): \n",
      "\n",
      "2021-08-11 01:30:18.958581 (INFO): \n",
      "2021-08-11 01:30:18.958628 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:30:18.958666 (INFO): dev_evaluation\n",
      "2021-08-11 01:30:19.012428 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:30:19.047945 (INFO): \n",
      "2021-08-11 01:30:51.383031 (INFO): Hits left @1: 0.0751953125\n",
      "2021-08-11 01:30:51.383542 (INFO): Hits right @1: 0.091796875\n",
      "2021-08-11 01:30:51.383826 (INFO): Hits @1: 0.08349609375\n",
      "2021-08-11 01:30:51.384009 (INFO): Hits left @2: 0.1435546875\n",
      "2021-08-11 01:30:51.384186 (INFO): Hits right @2: 0.173828125\n",
      "2021-08-11 01:30:51.384443 (INFO): Hits @2: 0.15869140625\n",
      "2021-08-11 01:30:51.385127 (INFO): Hits left @3: 0.2177734375\n",
      "2021-08-11 01:30:51.385330 (INFO): Hits right @3: 0.2421875\n",
      "2021-08-11 01:30:51.385595 (INFO): Hits @3: 0.22998046875\n",
      "2021-08-11 01:30:51.385769 (INFO): Hits left @4: 0.30859375\n",
      "2021-08-11 01:30:51.385975 (INFO): Hits right @4: 0.310546875\n",
      "2021-08-11 01:30:51.386231 (INFO): Hits @4: 0.3095703125\n",
      "2021-08-11 01:30:51.386401 (INFO): Hits left @5: 0.3779296875\n",
      "2021-08-11 01:30:51.386572 (INFO): Hits right @5: 0.3818359375\n",
      "2021-08-11 01:30:51.386823 (INFO): Hits @5: 0.3798828125\n",
      "2021-08-11 01:30:51.387000 (INFO): Hits left @6: 0.4521484375\n",
      "2021-08-11 01:30:51.387202 (INFO): Hits right @6: 0.44140625\n",
      "2021-08-11 01:30:51.388308 (INFO): Hits @6: 0.44677734375\n",
      "2021-08-11 01:30:51.388510 (INFO): Hits left @7: 0.51953125\n",
      "2021-08-11 01:30:51.388736 (INFO): Hits right @7: 0.5029296875\n",
      "2021-08-11 01:30:51.388997 (INFO): Hits @7: 0.51123046875\n",
      "2021-08-11 01:30:51.389171 (INFO): Hits left @8: 0.564453125\n",
      "2021-08-11 01:30:51.389343 (INFO): Hits right @8: 0.5498046875\n",
      "2021-08-11 01:30:51.389599 (INFO): Hits @8: 0.55712890625\n",
      "2021-08-11 01:30:51.389772 (INFO): Hits left @9: 0.625\n",
      "2021-08-11 01:30:51.389942 (INFO): Hits right @9: 0.61328125\n",
      "2021-08-11 01:30:51.390582 (INFO): Hits @9: 0.619140625\n",
      "2021-08-11 01:30:51.390756 (INFO): Hits left @10: 0.6708984375\n",
      "2021-08-11 01:30:51.390928 (INFO): Hits right @10: 0.666015625\n",
      "2021-08-11 01:30:51.391239 (INFO): Hits @10: 0.66845703125\n",
      "2021-08-11 01:30:51.391866 (INFO): Mean rank left: 9.3193359375\n",
      "2021-08-11 01:30:51.392052 (INFO): Mean rank right: 9.06640625\n",
      "2021-08-11 01:30:51.392302 (INFO): Mean rank: 9.19287109375\n",
      "2021-08-11 01:30:51.392493 (INFO): Mean reciprocal rank left: 0.2307425489581839\n",
      "2021-08-11 01:30:51.392950 (INFO): Mean reciprocal rank right: 0.24627347366006053\n",
      "2021-08-11 01:30:51.393864 (INFO): Mean reciprocal rank: 0.23850801130912225\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 01:30:51.532473 (INFO): \n",
      "2021-08-11 01:30:51.543209 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:30:51.543281 (INFO): test_evaluation\n",
      "2021-08-11 01:30:51.543325 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:30:51.543362 (INFO): \n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 01:31:19.573263 (INFO): Hits left @1: 0.0810546875\n",
      "2021-08-11 01:31:19.574288 (INFO): Hits right @1: 0.078125\n",
      "2021-08-11 01:31:19.574632 (INFO): Hits @1: 0.07958984375\n",
      "2021-08-11 01:31:19.575246 (INFO): Hits left @2: 0.1533203125\n",
      "2021-08-11 01:31:19.575433 (INFO): Hits right @2: 0.162109375\n",
      "2021-08-11 01:31:19.575697 (INFO): Hits @2: 0.15771484375\n",
      "2021-08-11 01:31:19.575870 (INFO): Hits left @3: 0.23828125\n",
      "2021-08-11 01:31:19.576041 (INFO): Hits right @3: 0.2373046875\n",
      "2021-08-11 01:31:19.576340 (INFO): Hits @3: 0.23779296875\n",
      "2021-08-11 01:31:19.576512 (INFO): Hits left @4: 0.3193359375\n",
      "2021-08-11 01:31:19.576682 (INFO): Hits right @4: 0.3125\n",
      "2021-08-11 01:31:19.576935 (INFO): Hits @4: 0.31591796875\n",
      "2021-08-11 01:31:19.577107 (INFO): Hits left @5: 0.3955078125\n",
      "2021-08-11 01:31:19.577277 (INFO): Hits right @5: 0.3779296875\n",
      "2021-08-11 01:31:19.577531 (INFO): Hits @5: 0.38671875\n",
      "2021-08-11 01:31:19.578088 (INFO): Hits left @6: 0.4541015625\n",
      "2021-08-11 01:31:19.578281 (INFO): Hits right @6: 0.455078125\n",
      "2021-08-11 01:31:19.578542 (INFO): Hits @6: 0.45458984375\n",
      "2021-08-11 01:31:19.578716 (INFO): Hits left @7: 0.5107421875\n",
      "2021-08-11 01:31:19.578888 (INFO): Hits right @7: 0.51171875\n",
      "2021-08-11 01:31:19.579637 (INFO): Hits @7: 0.51123046875\n",
      "2021-08-11 01:31:19.579812 (INFO): Hits left @8: 0.5595703125\n",
      "2021-08-11 01:31:19.579981 (INFO): Hits right @8: 0.5751953125\n",
      "2021-08-11 01:31:19.580234 (INFO): Hits @8: 0.5673828125\n",
      "2021-08-11 01:31:19.580705 (INFO): Hits left @9: 0.6015625\n",
      "2021-08-11 01:31:19.580901 (INFO): Hits right @9: 0.630859375\n",
      "2021-08-11 01:31:19.581169 (INFO): Hits @9: 0.6162109375\n",
      "2021-08-11 01:31:19.581347 (INFO): Hits left @10: 0.65234375\n",
      "2021-08-11 01:31:19.581520 (INFO): Hits right @10: 0.677734375\n",
      "2021-08-11 01:31:19.581773 (INFO): Hits @10: 0.6650390625\n",
      "2021-08-11 01:31:19.582005 (INFO): Mean rank left: 9.6630859375\n",
      "2021-08-11 01:31:19.582170 (INFO): Mean rank right: 9.087890625\n",
      "2021-08-11 01:31:19.582396 (INFO): Mean rank: 9.37548828125\n",
      "2021-08-11 01:31:19.582838 (INFO): Mean reciprocal rank left: 0.23677170568066225\n",
      "2021-08-11 01:31:19.583246 (INFO): Mean reciprocal rank right: 0.23775980365902966\n",
      "2021-08-11 01:31:19.583998 (INFO): Mean reciprocal rank: 0.23726575466984595\n",
      "2021-08-11 01:31:31.344531 (INFO): Total epoch time: 0:00:11\n",
      "2021-08-11 01:31:31.347482 (INFO): \n",
      "\n",
      "2021-08-11 01:31:31.348783 (INFO): ########################################\n",
      "2021-08-11 01:31:31.348913 (INFO):           COMPLETED EPOCH: 8                              \n",
      "2021-08-11 01:31:31.350116 (INFO): train Loss: 0.18645\t99% CI: (0.16856, 0.20434), n=23\n",
      "2021-08-11 01:31:31.350193 (INFO): ########################################\n",
      "2021-08-11 01:31:31.350240 (INFO): \n",
      "\n",
      "2021-08-11 01:31:42.081654 (INFO): Total epoch time: 0:00:10\n",
      "2021-08-11 01:31:42.169955 (INFO): \n",
      "\n",
      "2021-08-11 01:31:42.222450 (INFO): ########################################\n",
      "2021-08-11 01:31:42.240962 (INFO):           COMPLETED EPOCH: 9                              \n",
      "2021-08-11 01:31:42.247335 (INFO): train Loss: 0.16086\t99% CI: (0.14631, 0.1754), n=23\n",
      "2021-08-11 01:31:42.247399 (INFO): ########################################\n",
      "2021-08-11 01:31:42.247451 (INFO): \n",
      "\n",
      "2021-08-11 01:31:42.247633 (INFO): \n",
      "2021-08-11 01:31:42.247682 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:31:42.248580 (INFO): dev_evaluation\n",
      "2021-08-11 01:31:42.248657 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:31:42.248699 (INFO): \n",
      "2021-08-11 01:32:14.557090 (INFO): Hits left @1: 0.158203125\n",
      "2021-08-11 01:32:14.613966 (INFO): Hits right @1: 0.1337890625\n",
      "2021-08-11 01:32:14.652394 (INFO): Hits @1: 0.14599609375\n",
      "2021-08-11 01:32:14.652619 (INFO): Hits left @2: 0.2724609375\n",
      "2021-08-11 01:32:14.652802 (INFO): Hits right @2: 0.24609375\n",
      "2021-08-11 01:32:14.653065 (INFO): Hits @2: 0.25927734375\n",
      "2021-08-11 01:32:14.653239 (INFO): Hits left @3: 0.37109375\n",
      "2021-08-11 01:32:14.653455 (INFO): Hits right @3: 0.3408203125\n",
      "2021-08-11 01:32:14.653712 (INFO): Hits @3: 0.35595703125\n",
      "2021-08-11 01:32:14.653887 (INFO): Hits left @4: 0.4365234375\n",
      "2021-08-11 01:32:14.654080 (INFO): Hits right @4: 0.4248046875\n",
      "2021-08-11 01:32:14.654336 (INFO): Hits @4: 0.4306640625\n",
      "2021-08-11 01:32:14.654508 (INFO): Hits left @5: 0.5068359375\n",
      "2021-08-11 01:32:14.654678 (INFO): Hits right @5: 0.4931640625\n",
      "2021-08-11 01:32:14.655354 (INFO): Hits @5: 0.5\n",
      "2021-08-11 01:32:14.655539 (INFO): Hits left @6: 0.5693359375\n",
      "2021-08-11 01:32:14.656988 (INFO): Hits right @6: 0.5537109375\n",
      "2021-08-11 01:32:14.657355 (INFO): Hits @6: 0.5615234375\n",
      "2021-08-11 01:32:14.657554 (INFO): Hits left @7: 0.623046875\n",
      "2021-08-11 01:32:14.657740 (INFO): Hits right @7: 0.6181640625\n",
      "2021-08-11 01:32:14.658005 (INFO): Hits @7: 0.62060546875\n",
      "2021-08-11 01:32:14.658179 (INFO): Hits left @8: 0.6748046875\n",
      "2021-08-11 01:32:14.658349 (INFO): Hits right @8: 0.68359375\n",
      "2021-08-11 01:32:14.692023 (INFO): Hits @8: 0.67919921875\n",
      "2021-08-11 01:32:14.692684 (INFO): Hits left @9: 0.7119140625\n",
      "2021-08-11 01:32:14.693279 (INFO): Hits right @9: 0.7353515625\n",
      "2021-08-11 01:32:14.693545 (INFO): Hits @9: 0.7236328125\n",
      "2021-08-11 01:32:14.693719 (INFO): Hits left @10: 0.748046875\n",
      "2021-08-11 01:32:14.693890 (INFO): Hits right @10: 0.7744140625\n",
      "2021-08-11 01:32:14.694143 (INFO): Hits @10: 0.76123046875\n",
      "2021-08-11 01:32:14.694685 (INFO): Mean rank left: 7.5361328125\n",
      "2021-08-11 01:32:14.694874 (INFO): Mean rank right: 7.4990234375\n",
      "2021-08-11 01:32:14.695125 (INFO): Mean rank: 7.517578125\n",
      "2021-08-11 01:32:14.695312 (INFO): Mean reciprocal rank left: 0.3277266613003441\n",
      "2021-08-11 01:32:14.695957 (INFO): Mean reciprocal rank right: 0.3083191334903491\n",
      "2021-08-11 01:32:14.737523 (INFO): Mean reciprocal rank: 0.31802289739534656\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 01:32:14.789987 (INFO): \n",
      "2021-08-11 01:32:14.826131 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:32:14.826415 (INFO): test_evaluation\n",
      "2021-08-11 01:32:14.826462 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:32:14.826500 (INFO): \n",
      "2021-08-11 01:32:42.919077 (INFO): Hits left @1: 0.1630859375\n",
      "2021-08-11 01:32:42.919809 (INFO): Hits right @1: 0.1279296875\n",
      "2021-08-11 01:32:42.920266 (INFO): Hits @1: 0.1455078125\n",
      "2021-08-11 01:32:42.920591 (INFO): Hits left @2: 0.2802734375\n",
      "2021-08-11 01:32:42.921564 (INFO): Hits right @2: 0.234375\n",
      "2021-08-11 01:32:42.922051 (INFO): Hits @2: 0.25732421875\n",
      "2021-08-11 01:32:42.923089 (INFO): Hits left @3: 0.3603515625\n",
      "2021-08-11 01:32:42.923475 (INFO): Hits right @3: 0.333984375\n",
      "2021-08-11 01:32:42.924481 (INFO): Hits @3: 0.34716796875\n",
      "2021-08-11 01:32:42.924797 (INFO): Hits left @4: 0.4375\n",
      "2021-08-11 01:32:42.925675 (INFO): Hits right @4: 0.4208984375\n",
      "2021-08-11 01:32:42.926155 (INFO): Hits @4: 0.42919921875\n",
      "2021-08-11 01:32:42.927097 (INFO): Hits left @5: 0.51171875\n",
      "2021-08-11 01:32:42.927442 (INFO): Hits right @5: 0.4931640625\n",
      "2021-08-11 01:32:42.928558 (INFO): Hits @5: 0.50244140625\n",
      "2021-08-11 01:32:42.928844 (INFO): Hits left @6: 0.5849609375\n",
      "2021-08-11 01:32:42.929405 (INFO): Hits right @6: 0.5654296875\n",
      "2021-08-11 01:32:42.929684 (INFO): Hits @6: 0.5751953125\n",
      "2021-08-11 01:32:42.930023 (INFO): Hits left @7: 0.6494140625\n",
      "2021-08-11 01:32:42.930399 (INFO): Hits right @7: 0.6328125\n",
      "2021-08-11 01:32:42.942226 (INFO): Hits @7: 0.64111328125\n",
      "2021-08-11 01:32:42.942526 (INFO): Hits left @8: 0.69140625\n",
      "2021-08-11 01:32:42.942778 (INFO): Hits right @8: 0.6875\n",
      "2021-08-11 01:32:42.943788 (INFO): Hits @8: 0.689453125\n",
      "2021-08-11 01:32:42.944194 (INFO): Hits left @9: 0.732421875\n",
      "2021-08-11 01:32:42.956480 (INFO): Hits right @9: 0.72265625\n",
      "2021-08-11 01:32:42.957107 (INFO): Hits @9: 0.7275390625\n",
      "2021-08-11 01:32:42.957456 (INFO): Hits left @10: 0.7626953125\n",
      "2021-08-11 01:32:42.957707 (INFO): Hits right @10: 0.7646484375\n",
      "2021-08-11 01:32:42.957978 (INFO): Hits @10: 0.763671875\n",
      "2021-08-11 01:32:42.983585 (INFO): Mean rank left: 7.490234375\n",
      "2021-08-11 01:32:43.009897 (INFO): Mean rank right: 7.3564453125\n",
      "2021-08-11 01:32:43.011276 (INFO): Mean rank: 7.42333984375\n",
      "2021-08-11 01:32:43.012373 (INFO): Mean reciprocal rank left: 0.33202258493111664\n",
      "2021-08-11 01:32:43.012760 (INFO): Mean reciprocal rank right: 0.3028580557564178\n",
      "2021-08-11 01:32:43.014457 (INFO): Mean reciprocal rank: 0.31744032034376723\n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 01:32:53.864102 (INFO): Total epoch time: 0:00:10\n",
      "2021-08-11 01:32:53.865255 (INFO): \n",
      "\n",
      "2021-08-11 01:32:53.899978 (INFO): ########################################\n",
      "2021-08-11 01:32:53.921692 (INFO):           COMPLETED EPOCH: 10                              \n",
      "2021-08-11 01:32:53.944452 (INFO): train Loss: 0.16465\t99% CI: (0.1496, 0.17971), n=23\n",
      "2021-08-11 01:32:53.944538 (INFO): ########################################\n",
      "2021-08-11 01:32:53.944586 (INFO): \n",
      "\n",
      "2021-08-11 01:33:06.240679 (INFO): Total epoch time: 0:00:12\n",
      "2021-08-11 01:33:06.241700 (INFO): \n",
      "\n",
      "2021-08-11 01:33:06.241780 (INFO): ########################################\n",
      "2021-08-11 01:33:06.241828 (INFO):           COMPLETED EPOCH: 11                              \n",
      "2021-08-11 01:33:06.241868 (INFO): train Loss: 0.1608\t99% CI: (0.14711, 0.17449), n=23\n",
      "2021-08-11 01:33:06.241904 (INFO): ########################################\n",
      "2021-08-11 01:33:06.241940 (INFO): \n",
      "\n",
      "2021-08-11 01:33:06.242115 (INFO): \n",
      "2021-08-11 01:33:06.266511 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:33:06.266603 (INFO): dev_evaluation\n",
      "2021-08-11 01:33:06.266648 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:33:06.266686 (INFO): \n",
      "2021-08-11 01:33:36.024641 (INFO): Hits left @1: 0.3017578125\n",
      "2021-08-11 01:33:36.025605 (INFO): Hits right @1: 0.275390625\n",
      "2021-08-11 01:33:36.025898 (INFO): Hits @1: 0.28857421875\n",
      "2021-08-11 01:33:36.026083 (INFO): Hits left @2: 0.453125\n",
      "2021-08-11 01:33:36.026662 (INFO): Hits right @2: 0.3955078125\n",
      "2021-08-11 01:33:36.026920 (INFO): Hits @2: 0.42431640625\n",
      "2021-08-11 01:33:36.027093 (INFO): Hits left @3: 0.5400390625\n",
      "2021-08-11 01:33:36.027265 (INFO): Hits right @3: 0.4716796875\n",
      "2021-08-11 01:33:36.027517 (INFO): Hits @3: 0.505859375\n",
      "2021-08-11 01:33:36.028028 (INFO): Hits left @4: 0.6123046875\n",
      "2021-08-11 01:33:36.028228 (INFO): Hits right @4: 0.556640625\n",
      "2021-08-11 01:33:36.028502 (INFO): Hits @4: 0.58447265625\n",
      "2021-08-11 01:33:36.028679 (INFO): Hits left @5: 0.662109375\n",
      "2021-08-11 01:33:36.028853 (INFO): Hits right @5: 0.6171875\n",
      "2021-08-11 01:33:36.029415 (INFO): Hits @5: 0.6396484375\n",
      "2021-08-11 01:33:36.029595 (INFO): Hits left @6: 0.7080078125\n",
      "2021-08-11 01:33:36.029769 (INFO): Hits right @6: 0.6611328125\n",
      "2021-08-11 01:33:36.030025 (INFO): Hits @6: 0.6845703125\n",
      "2021-08-11 01:33:36.030196 (INFO): Hits left @7: 0.7451171875\n",
      "2021-08-11 01:33:36.030723 (INFO): Hits right @7: 0.7021484375\n",
      "2021-08-11 01:33:36.031010 (INFO): Hits @7: 0.7236328125\n",
      "2021-08-11 01:33:36.031193 (INFO): Hits left @8: 0.7802734375\n",
      "2021-08-11 01:33:36.031370 (INFO): Hits right @8: 0.7529296875\n",
      "2021-08-11 01:33:36.031627 (INFO): Hits @8: 0.7666015625\n",
      "2021-08-11 01:33:36.055158 (INFO): Hits left @9: 0.8115234375\n",
      "2021-08-11 01:33:36.077767 (INFO): Hits right @9: 0.7890625\n",
      "2021-08-11 01:33:36.078069 (INFO): Hits @9: 0.80029296875\n",
      "2021-08-11 01:33:36.078253 (INFO): Hits left @10: 0.837890625\n",
      "2021-08-11 01:33:36.078430 (INFO): Hits right @10: 0.8193359375\n",
      "2021-08-11 01:33:36.079248 (INFO): Hits @10: 0.82861328125\n",
      "2021-08-11 01:33:36.127319 (INFO): Mean rank left: 5.8642578125\n",
      "2021-08-11 01:33:36.186648 (INFO): Mean rank right: 6.162109375\n",
      "2021-08-11 01:33:36.198419 (INFO): Mean rank: 6.01318359375\n",
      "2021-08-11 01:33:36.198625 (INFO): Mean reciprocal rank left: 0.468063290294344\n",
      "2021-08-11 01:33:36.198799 (INFO): Mean reciprocal rank right: 0.4329691581804966\n",
      "2021-08-11 01:33:36.199037 (INFO): Mean reciprocal rank: 0.4505162242374203\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 01:33:36.294806 (INFO): \n",
      "2021-08-11 01:33:36.295301 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:33:36.295351 (INFO): test_evaluation\n",
      "2021-08-11 01:33:36.295389 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:33:36.295425 (INFO): \n",
      "2021-08-11 01:34:05.890299 (INFO): Hits left @1: 0.30859375\n",
      "2021-08-11 01:34:05.890853 (INFO): Hits right @1: 0.23828125\n",
      "2021-08-11 01:34:05.891154 (INFO): Hits @1: 0.2734375\n",
      "2021-08-11 01:34:05.891348 (INFO): Hits left @2: 0.4326171875\n",
      "2021-08-11 01:34:05.891528 (INFO): Hits right @2: 0.373046875\n",
      "2021-08-11 01:34:05.891789 (INFO): Hits @2: 0.40283203125\n",
      "2021-08-11 01:34:05.892520 (INFO): Hits left @3: 0.51953125\n",
      "2021-08-11 01:34:05.892714 (INFO): Hits right @3: 0.466796875\n",
      "2021-08-11 01:34:05.892988 (INFO): Hits @3: 0.4931640625\n",
      "2021-08-11 01:34:05.893164 (INFO): Hits left @4: 0.591796875\n",
      "2021-08-11 01:34:05.923537 (INFO): Hits right @4: 0.5390625\n",
      "2021-08-11 01:34:05.969177 (INFO): Hits @4: 0.5654296875\n",
      "2021-08-11 01:34:05.970242 (INFO): Hits left @5: 0.6435546875\n",
      "2021-08-11 01:34:05.970530 (INFO): Hits right @5: 0.6123046875\n",
      "2021-08-11 01:34:05.984433 (INFO): Hits @5: 0.6279296875\n",
      "2021-08-11 01:34:05.985419 (INFO): Hits left @6: 0.69140625\n",
      "2021-08-11 01:34:05.985625 (INFO): Hits right @6: 0.658203125\n",
      "2021-08-11 01:34:05.985891 (INFO): Hits @6: 0.6748046875\n",
      "2021-08-11 01:34:05.986428 (INFO): Hits left @7: 0.7490234375\n",
      "2021-08-11 01:34:05.987331 (INFO): Hits right @7: 0.70703125\n",
      "2021-08-11 01:34:05.987993 (INFO): Hits @7: 0.72802734375\n",
      "2021-08-11 01:34:05.988183 (INFO): Hits left @8: 0.77734375\n",
      "2021-08-11 01:34:05.988357 (INFO): Hits right @8: 0.7529296875\n",
      "2021-08-11 01:34:05.988624 (INFO): Hits @8: 0.76513671875\n",
      "2021-08-11 01:34:05.988794 (INFO): Hits left @9: 0.8095703125\n",
      "2021-08-11 01:34:05.989364 (INFO): Hits right @9: 0.7890625\n",
      "2021-08-11 01:34:05.989646 (INFO): Hits @9: 0.79931640625\n",
      "2021-08-11 01:34:05.997268 (INFO): Hits left @10: 0.8251953125\n",
      "2021-08-11 01:34:06.009459 (INFO): Hits right @10: 0.81640625\n",
      "2021-08-11 01:34:06.009770 (INFO): Hits @10: 0.82080078125\n",
      "2021-08-11 01:34:06.009986 (INFO): Mean rank left: 5.951171875\n",
      "2021-08-11 01:34:06.010303 (INFO): Mean rank right: 6.12890625\n",
      "2021-08-11 01:34:06.010582 (INFO): Mean rank: 6.0400390625\n",
      "2021-08-11 01:34:06.010779 (INFO): Mean reciprocal rank left: 0.4640645087537027\n",
      "2021-08-11 01:34:06.011592 (INFO): Mean reciprocal rank right: 0.4088701256608377\n",
      "2021-08-11 01:34:06.012174 (INFO): Mean reciprocal rank: 0.4364673172072702\n",
      "2021-08-11 01:34:16.969056 (INFO): Total epoch time: 0:00:10\n",
      "2021-08-11 01:34:16.976682 (INFO): \n",
      "\n",
      "2021-08-11 01:34:16.976753 (INFO): ########################################\n",
      "2021-08-11 01:34:16.977108 (INFO):           COMPLETED EPOCH: 12                              \n",
      "2021-08-11 01:34:16.977156 (INFO): train Loss: 0.15286\t99% CI: (0.1413, 0.16442), n=23\n",
      "2021-08-11 01:34:16.977196 (INFO): ########################################\n",
      "2021-08-11 01:34:16.977232 (INFO): \n",
      "\n",
      "2021-08-11 01:34:28.827888 (INFO): Total epoch time: 0:00:11\n",
      "2021-08-11 01:34:28.828963 (INFO): \n",
      "\n",
      "2021-08-11 01:34:28.829033 (INFO): ########################################\n",
      "2021-08-11 01:34:28.829079 (INFO):           COMPLETED EPOCH: 13                              \n",
      "2021-08-11 01:34:28.829117 (INFO): train Loss: 0.14074\t99% CI: (0.12857, 0.15292), n=23\n",
      "2021-08-11 01:34:28.829156 (INFO): ########################################\n",
      "2021-08-11 01:34:28.829194 (INFO): \n",
      "\n",
      "2021-08-11 01:34:28.829364 (INFO): \n",
      "2021-08-11 01:34:28.829912 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:34:28.829953 (INFO): dev_evaluation\n",
      "2021-08-11 01:34:28.829990 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:34:28.830025 (INFO): \n",
      "2021-08-11 01:34:58.621087 (INFO): Hits left @1: 0.3642578125\n",
      "2021-08-11 01:34:58.627989 (INFO): Hits right @1: 0.30078125\n",
      "2021-08-11 01:34:58.640170 (INFO): Hits @1: 0.33251953125\n",
      "2021-08-11 01:34:58.682668 (INFO): Hits left @2: 0.51953125\n",
      "2021-08-11 01:34:58.683581 (INFO): Hits right @2: 0.4267578125\n",
      "2021-08-11 01:34:58.683861 (INFO): Hits @2: 0.47314453125\n",
      "2021-08-11 01:34:58.684049 (INFO): Hits left @3: 0.6015625\n",
      "2021-08-11 01:34:58.684715 (INFO): Hits right @3: 0.5185546875\n",
      "2021-08-11 01:34:58.685093 (INFO): Hits @3: 0.56005859375\n",
      "2021-08-11 01:34:58.685324 (INFO): Hits left @4: 0.6669921875\n",
      "2021-08-11 01:34:58.685513 (INFO): Hits right @4: 0.5810546875\n",
      "2021-08-11 01:34:58.686216 (INFO): Hits @4: 0.6240234375\n",
      "2021-08-11 01:34:58.692048 (INFO): Hits left @5: 0.7041015625\n",
      "2021-08-11 01:34:58.722897 (INFO): Hits right @5: 0.6396484375\n",
      "2021-08-11 01:34:58.734384 (INFO): Hits @5: 0.671875\n",
      "2021-08-11 01:34:58.734611 (INFO): Hits left @6: 0.7470703125\n",
      "2021-08-11 01:34:58.734877 (INFO): Hits right @6: 0.689453125\n",
      "2021-08-11 01:34:58.735163 (INFO): Hits @6: 0.71826171875\n",
      "2021-08-11 01:34:58.735348 (INFO): Hits left @7: 0.791015625\n",
      "2021-08-11 01:34:58.735525 (INFO): Hits right @7: 0.7412109375\n",
      "2021-08-11 01:34:58.735783 (INFO): Hits @7: 0.76611328125\n",
      "2021-08-11 01:34:58.735958 (INFO): Hits left @8: 0.818359375\n",
      "2021-08-11 01:34:58.736576 (INFO): Hits right @8: 0.791015625\n",
      "2021-08-11 01:34:58.736839 (INFO): Hits @8: 0.8046875\n",
      "2021-08-11 01:34:58.737013 (INFO): Hits left @9: 0.8515625\n",
      "2021-08-11 01:34:58.737186 (INFO): Hits right @9: 0.8310546875\n",
      "2021-08-11 01:34:58.737447 (INFO): Hits @9: 0.84130859375\n",
      "2021-08-11 01:34:58.738017 (INFO): Hits left @10: 0.8681640625\n",
      "2021-08-11 01:34:58.738215 (INFO): Hits right @10: 0.859375\n",
      "2021-08-11 01:34:58.738479 (INFO): Hits @10: 0.86376953125\n",
      "2021-08-11 01:34:58.738725 (INFO): Mean rank left: 5.26171875\n",
      "2021-08-11 01:34:58.739017 (INFO): Mean rank right: 5.6220703125\n",
      "2021-08-11 01:34:58.739272 (INFO): Mean rank: 5.44189453125\n",
      "2021-08-11 01:34:58.739754 (INFO): Mean reciprocal rank left: 0.5236085347193958\n",
      "2021-08-11 01:34:58.740172 (INFO): Mean reciprocal rank right: 0.46038897010754576\n",
      "2021-08-11 01:34:58.740522 (INFO): Mean reciprocal rank: 0.4919987524134708\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 01:34:58.928041 (INFO): \n",
      "2021-08-11 01:34:58.987563 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:34:58.987638 (INFO): test_evaluation\n",
      "2021-08-11 01:34:58.987687 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:34:58.987755 (INFO): \n",
      "2021-08-11 01:35:28.307299 (INFO): Hits left @1: 0.32421875\n",
      "2021-08-11 01:35:28.307767 (INFO): Hits right @1: 0.2666015625\n",
      "2021-08-11 01:35:28.308054 (INFO): Hits @1: 0.29541015625\n",
      "2021-08-11 01:35:28.308239 (INFO): Hits left @2: 0.4541015625\n",
      "2021-08-11 01:35:28.308423 (INFO): Hits right @2: 0.3955078125\n",
      "2021-08-11 01:35:28.308685 (INFO): Hits @2: 0.4248046875\n",
      "2021-08-11 01:35:28.314708 (INFO): Hits left @3: 0.55859375\n",
      "2021-08-11 01:35:28.314918 (INFO): Hits right @3: 0.4892578125\n",
      "2021-08-11 01:35:28.315187 (INFO): Hits @3: 0.52392578125\n",
      "2021-08-11 01:35:28.315365 (INFO): Hits left @4: 0.6298828125\n",
      "2021-08-11 01:35:28.315926 (INFO): Hits right @4: 0.5625\n",
      "2021-08-11 01:35:28.316203 (INFO): Hits @4: 0.59619140625\n",
      "2021-08-11 01:35:28.316387 (INFO): Hits left @5: 0.6904296875\n",
      "2021-08-11 01:35:28.316563 (INFO): Hits right @5: 0.62890625\n",
      "2021-08-11 01:35:28.316814 (INFO): Hits @5: 0.65966796875\n",
      "2021-08-11 01:35:28.317272 (INFO): Hits left @6: 0.7421875\n",
      "2021-08-11 01:35:28.317446 (INFO): Hits right @6: 0.6943359375\n",
      "2021-08-11 01:35:28.317698 (INFO): Hits @6: 0.71826171875\n",
      "2021-08-11 01:35:28.317868 (INFO): Hits left @7: 0.7802734375\n",
      "2021-08-11 01:35:28.318035 (INFO): Hits right @7: 0.7392578125\n",
      "2021-08-11 01:35:28.318284 (INFO): Hits @7: 0.759765625\n",
      "2021-08-11 01:35:28.318485 (INFO): Hits left @8: 0.814453125\n",
      "2021-08-11 01:35:28.318656 (INFO): Hits right @8: 0.7880859375\n",
      "2021-08-11 01:35:28.318909 (INFO): Hits @8: 0.80126953125\n",
      "2021-08-11 01:35:28.319077 (INFO): Hits left @9: 0.8408203125\n",
      "2021-08-11 01:35:28.319244 (INFO): Hits right @9: 0.828125\n",
      "2021-08-11 01:35:28.319496 (INFO): Hits @9: 0.83447265625\n",
      "2021-08-11 01:35:28.319665 (INFO): Hits left @10: 0.853515625\n",
      "2021-08-11 01:35:28.319865 (INFO): Hits right @10: 0.849609375\n",
      "2021-08-11 01:35:28.320116 (INFO): Hits @10: 0.8515625\n",
      "2021-08-11 01:35:28.320299 (INFO): Mean rank left: 5.4775390625\n",
      "2021-08-11 01:35:28.320458 (INFO): Mean rank right: 5.595703125\n",
      "2021-08-11 01:35:28.320680 (INFO): Mean rank: 5.53662109375\n",
      "2021-08-11 01:35:28.333033 (INFO): Mean reciprocal rank left: 0.48575072462751445\n",
      "2021-08-11 01:35:28.425471 (INFO): Mean reciprocal rank right: 0.4341466850865198\n",
      "2021-08-11 01:35:28.425865 (INFO): Mean reciprocal rank: 0.45994870485701717\n",
      "2021-08-11 01:35:38.280359 (INFO): Total epoch time: 0:00:09\n",
      "2021-08-11 01:35:38.283292 (INFO): \n",
      "\n",
      "2021-08-11 01:35:38.284138 (INFO): ########################################\n",
      "2021-08-11 01:35:38.284255 (INFO):           COMPLETED EPOCH: 14                              \n",
      "2021-08-11 01:35:38.284425 (INFO): train Loss: 0.14962\t99% CI: (0.13754, 0.16171), n=23\n",
      "2021-08-11 01:35:38.284521 (INFO): ########################################\n",
      "2021-08-11 01:35:38.284583 (INFO): \n",
      "\n",
      "2021-08-11 01:35:48.653842 (INFO): Total epoch time: 0:00:10\n",
      "2021-08-11 01:35:48.683717 (INFO): \n",
      "\n",
      "2021-08-11 01:35:48.684131 (INFO): ########################################\n",
      "2021-08-11 01:35:48.684194 (INFO):           COMPLETED EPOCH: 15                              \n",
      "2021-08-11 01:35:48.684241 (INFO): train Loss: 0.14495\t99% CI: (0.13388, 0.15603), n=23\n",
      "2021-08-11 01:35:48.684278 (INFO): ########################################\n",
      "2021-08-11 01:35:48.684313 (INFO): \n",
      "\n",
      "2021-08-11 01:35:48.684492 (INFO): \n",
      "2021-08-11 01:35:48.684542 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:35:48.684580 (INFO): dev_evaluation\n",
      "2021-08-11 01:35:48.690589 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:35:48.709520 (INFO): \n",
      "2021-08-11 01:36:16.419568 (INFO): Hits left @1: 0.3974609375\n",
      "2021-08-11 01:36:16.426480 (INFO): Hits right @1: 0.3369140625\n",
      "2021-08-11 01:36:16.426785 (INFO): Hits @1: 0.3671875\n",
      "2021-08-11 01:36:16.426972 (INFO): Hits left @2: 0.5439453125\n",
      "2021-08-11 01:36:16.427167 (INFO): Hits right @2: 0.4677734375\n",
      "2021-08-11 01:36:16.433799 (INFO): Hits @2: 0.505859375\n",
      "2021-08-11 01:36:16.434000 (INFO): Hits left @3: 0.619140625\n",
      "2021-08-11 01:36:16.434191 (INFO): Hits right @3: 0.548828125\n",
      "2021-08-11 01:36:16.434447 (INFO): Hits @3: 0.583984375\n",
      "2021-08-11 01:36:16.434619 (INFO): Hits left @4: 0.66796875\n",
      "2021-08-11 01:36:16.435386 (INFO): Hits right @4: 0.6005859375\n",
      "2021-08-11 01:36:16.435662 (INFO): Hits @4: 0.63427734375\n",
      "2021-08-11 01:36:16.435845 (INFO): Hits left @5: 0.7041015625\n",
      "2021-08-11 01:36:16.436038 (INFO): Hits right @5: 0.6591796875\n",
      "2021-08-11 01:36:16.546557 (INFO): Hits @5: 0.681640625\n",
      "2021-08-11 01:36:16.547156 (INFO): Hits left @6: 0.7568359375\n",
      "2021-08-11 01:36:16.547363 (INFO): Hits right @6: 0.7060546875\n",
      "2021-08-11 01:36:16.547632 (INFO): Hits @6: 0.7314453125\n",
      "2021-08-11 01:36:16.547819 (INFO): Hits left @7: 0.7939453125\n",
      "2021-08-11 01:36:16.547994 (INFO): Hits right @7: 0.7666015625\n",
      "2021-08-11 01:36:16.606689 (INFO): Hits @7: 0.7802734375\n",
      "2021-08-11 01:36:16.734901 (INFO): Hits left @8: 0.830078125\n",
      "2021-08-11 01:36:16.808488 (INFO): Hits right @8: 0.8076171875\n",
      "2021-08-11 01:36:16.809481 (INFO): Hits @8: 0.81884765625\n",
      "2021-08-11 01:36:16.809682 (INFO): Hits left @9: 0.857421875\n",
      "2021-08-11 01:36:16.809862 (INFO): Hits right @9: 0.8408203125\n",
      "2021-08-11 01:36:16.810728 (INFO): Hits @9: 0.84912109375\n",
      "2021-08-11 01:36:16.810928 (INFO): Hits left @10: 0.8720703125\n",
      "2021-08-11 01:36:16.811109 (INFO): Hits right @10: 0.8671875\n",
      "2021-08-11 01:36:16.811368 (INFO): Hits @10: 0.86962890625\n",
      "2021-08-11 01:36:16.811847 (INFO): Mean rank left: 4.986328125\n",
      "2021-08-11 01:36:16.812044 (INFO): Mean rank right: 5.384765625\n",
      "2021-08-11 01:36:16.812284 (INFO): Mean rank: 5.185546875\n",
      "2021-08-11 01:36:16.812464 (INFO): Mean reciprocal rank left: 0.5467584742611258\n",
      "2021-08-11 01:36:16.813135 (INFO): Mean reciprocal rank right: 0.49087162853409455\n",
      "2021-08-11 01:36:16.814263 (INFO): Mean reciprocal rank: 0.5188150513976102\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 01:36:16.825117 (INFO): \n",
      "2021-08-11 01:36:16.825931 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:36:16.831624 (INFO): test_evaluation\n",
      "2021-08-11 01:36:16.831691 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:36:16.831733 (INFO): \n",
      "2021-08-11 01:36:43.518770 (INFO): Hits left @1: 0.3671875\n",
      "2021-08-11 01:36:43.520288 (INFO): Hits right @1: 0.3154296875\n",
      "2021-08-11 01:36:43.521226 (INFO): Hits @1: 0.34130859375\n",
      "2021-08-11 01:36:43.521444 (INFO): Hits left @2: 0.50390625\n",
      "2021-08-11 01:36:43.521626 (INFO): Hits right @2: 0.4306640625\n",
      "2021-08-11 01:36:43.522494 (INFO): Hits @2: 0.46728515625\n",
      "2021-08-11 01:36:43.522773 (INFO): Hits left @3: 0.6025390625\n",
      "2021-08-11 01:36:43.522996 (INFO): Hits right @3: 0.515625\n",
      "2021-08-11 01:36:43.523671 (INFO): Hits @3: 0.55908203125\n",
      "2021-08-11 01:36:43.523882 (INFO): Hits left @4: 0.6767578125\n",
      "2021-08-11 01:36:43.524066 (INFO): Hits right @4: 0.5908203125\n",
      "2021-08-11 01:36:43.524340 (INFO): Hits @4: 0.6337890625\n",
      "2021-08-11 01:36:43.525013 (INFO): Hits left @5: 0.7236328125\n",
      "2021-08-11 01:36:43.525208 (INFO): Hits right @5: 0.654296875\n",
      "2021-08-11 01:36:43.525471 (INFO): Hits @5: 0.68896484375\n",
      "2021-08-11 01:36:43.525653 (INFO): Hits left @6: 0.78125\n",
      "2021-08-11 01:36:43.525882 (INFO): Hits right @6: 0.6982421875\n",
      "2021-08-11 01:36:43.526318 (INFO): Hits @6: 0.73974609375\n",
      "2021-08-11 01:36:43.526496 (INFO): Hits left @7: 0.818359375\n",
      "2021-08-11 01:36:43.526671 (INFO): Hits right @7: 0.7490234375\n",
      "2021-08-11 01:36:43.526984 (INFO): Hits @7: 0.78369140625\n",
      "2021-08-11 01:36:43.527259 (INFO): Hits left @8: 0.833984375\n",
      "2021-08-11 01:36:43.527456 (INFO): Hits right @8: 0.802734375\n",
      "2021-08-11 01:36:43.527719 (INFO): Hits @8: 0.818359375\n",
      "2021-08-11 01:36:43.527894 (INFO): Hits left @9: 0.8505859375\n",
      "2021-08-11 01:36:43.528064 (INFO): Hits right @9: 0.8349609375\n",
      "2021-08-11 01:36:43.528320 (INFO): Hits @9: 0.8427734375\n",
      "2021-08-11 01:36:43.529016 (INFO): Hits left @10: 0.8671875\n",
      "2021-08-11 01:36:43.529215 (INFO): Hits right @10: 0.8662109375\n",
      "2021-08-11 01:36:43.529553 (INFO): Hits @10: 0.86669921875\n",
      "2021-08-11 01:36:43.529756 (INFO): Mean rank left: 5.046875\n",
      "2021-08-11 01:36:43.529965 (INFO): Mean rank right: 5.3564453125\n",
      "2021-08-11 01:36:43.530196 (INFO): Mean rank: 5.20166015625\n",
      "2021-08-11 01:36:43.530381 (INFO): Mean reciprocal rank left: 0.5250401029836564\n",
      "2021-08-11 01:36:43.530903 (INFO): Mean reciprocal rank right: 0.4698249965020692\n",
      "2021-08-11 01:36:43.531186 (INFO): Mean reciprocal rank: 0.4974325497428629\n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 01:36:55.956313 (INFO): Total epoch time: 0:00:12\n",
      "2021-08-11 01:36:55.957767 (INFO): \n",
      "\n",
      "2021-08-11 01:36:55.957883 (INFO): ########################################\n",
      "2021-08-11 01:36:55.957935 (INFO):           COMPLETED EPOCH: 16                              \n",
      "2021-08-11 01:36:55.957976 (INFO): train Loss: 0.15725\t99% CI: (0.14808, 0.16642), n=23\n",
      "2021-08-11 01:36:55.958014 (INFO): ########################################\n",
      "2021-08-11 01:36:55.958051 (INFO): \n",
      "\n",
      "2021-08-11 01:37:07.636330 (INFO): Total epoch time: 0:00:11\n",
      "2021-08-11 01:37:07.640217 (INFO): \n",
      "\n",
      "2021-08-11 01:37:07.641133 (INFO): ########################################\n",
      "2021-08-11 01:37:07.641246 (INFO):           COMPLETED EPOCH: 17                              \n",
      "2021-08-11 01:37:07.641325 (INFO): train Loss: 0.15144\t99% CI: (0.14128, 0.16161), n=23\n",
      "2021-08-11 01:37:07.641400 (INFO): ########################################\n",
      "2021-08-11 01:37:07.641468 (INFO): \n",
      "\n",
      "2021-08-11 01:37:07.641720 (INFO): \n",
      "2021-08-11 01:37:07.641877 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:37:07.641992 (INFO): dev_evaluation\n",
      "2021-08-11 01:37:07.642061 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:37:07.642130 (INFO): \n",
      "2021-08-11 01:37:37.042236 (INFO): Hits left @1: 0.412109375\n",
      "2021-08-11 01:37:37.042718 (INFO): Hits right @1: 0.3466796875\n",
      "2021-08-11 01:37:37.042999 (INFO): Hits @1: 0.37939453125\n",
      "2021-08-11 01:37:37.043179 (INFO): Hits left @2: 0.548828125\n",
      "2021-08-11 01:37:37.043352 (INFO): Hits right @2: 0.4716796875\n",
      "2021-08-11 01:37:37.043608 (INFO): Hits @2: 0.51025390625\n",
      "2021-08-11 01:37:37.043874 (INFO): Hits left @3: 0.62890625\n",
      "2021-08-11 01:37:37.044070 (INFO): Hits right @3: 0.5634765625\n",
      "2021-08-11 01:37:37.044334 (INFO): Hits @3: 0.59619140625\n",
      "2021-08-11 01:37:37.044511 (INFO): Hits left @4: 0.67578125\n",
      "2021-08-11 01:37:37.044683 (INFO): Hits right @4: 0.619140625\n",
      "2021-08-11 01:37:37.044937 (INFO): Hits @4: 0.6474609375\n",
      "2021-08-11 01:37:37.045184 (INFO): Hits left @5: 0.7265625\n",
      "2021-08-11 01:37:37.045368 (INFO): Hits right @5: 0.6796875\n",
      "2021-08-11 01:37:37.045634 (INFO): Hits @5: 0.703125\n",
      "2021-08-11 01:37:37.045805 (INFO): Hits left @6: 0.7734375\n",
      "2021-08-11 01:37:37.045978 (INFO): Hits right @6: 0.720703125\n",
      "2021-08-11 01:37:37.046229 (INFO): Hits @6: 0.7470703125\n",
      "2021-08-11 01:37:37.046886 (INFO): Hits left @7: 0.8056640625\n",
      "2021-08-11 01:37:37.047064 (INFO): Hits right @7: 0.763671875\n",
      "2021-08-11 01:37:37.047317 (INFO): Hits @7: 0.78466796875\n",
      "2021-08-11 01:37:37.047487 (INFO): Hits left @8: 0.8349609375\n",
      "2021-08-11 01:37:37.047654 (INFO): Hits right @8: 0.8017578125\n",
      "2021-08-11 01:37:37.048279 (INFO): Hits @8: 0.818359375\n",
      "2021-08-11 01:37:37.048479 (INFO): Hits left @9: 0.8544921875\n",
      "2021-08-11 01:37:37.048661 (INFO): Hits right @9: 0.8388671875\n",
      "2021-08-11 01:37:37.048919 (INFO): Hits @9: 0.8466796875\n",
      "2021-08-11 01:37:37.049098 (INFO): Hits left @10: 0.873046875\n",
      "2021-08-11 01:37:37.049621 (INFO): Hits right @10: 0.869140625\n",
      "2021-08-11 01:37:37.049889 (INFO): Hits @10: 0.87109375\n",
      "2021-08-11 01:37:37.050072 (INFO): Mean rank left: 4.7939453125\n",
      "2021-08-11 01:37:37.050234 (INFO): Mean rank right: 5.24609375\n",
      "2021-08-11 01:37:37.050457 (INFO): Mean rank: 5.02001953125\n",
      "2021-08-11 01:37:37.050978 (INFO): Mean reciprocal rank left: 0.5575597644811492\n",
      "2021-08-11 01:37:37.061829 (INFO): Mean reciprocal rank right: 0.49951825834150176\n",
      "2021-08-11 01:37:37.179531 (INFO): Mean reciprocal rank: 0.5285390114113253\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 01:37:37.221409 (INFO): \n",
      "2021-08-11 01:37:37.221572 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:37:37.221630 (INFO): test_evaluation\n",
      "2021-08-11 01:37:37.221671 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:37:37.221707 (INFO): \n",
      "2021-08-11 01:38:07.537199 (INFO): Hits left @1: 0.3779296875\n",
      "2021-08-11 01:38:07.537799 (INFO): Hits right @1: 0.32421875\n",
      "2021-08-11 01:38:07.538088 (INFO): Hits @1: 0.35107421875\n",
      "2021-08-11 01:38:07.538271 (INFO): Hits left @2: 0.52734375\n",
      "2021-08-11 01:38:07.538451 (INFO): Hits right @2: 0.4541015625\n",
      "2021-08-11 01:38:07.538728 (INFO): Hits @2: 0.49072265625\n",
      "2021-08-11 01:38:07.539000 (INFO): Hits left @3: 0.62109375\n",
      "2021-08-11 01:38:07.539199 (INFO): Hits right @3: 0.5419921875\n",
      "2021-08-11 01:38:07.539462 (INFO): Hits @3: 0.58154296875\n",
      "2021-08-11 01:38:07.539643 (INFO): Hits left @4: 0.693359375\n",
      "2021-08-11 01:38:07.539823 (INFO): Hits right @4: 0.6142578125\n",
      "2021-08-11 01:38:07.540076 (INFO): Hits @4: 0.65380859375\n",
      "2021-08-11 01:38:07.574461 (INFO): Hits left @5: 0.7421875\n",
      "2021-08-11 01:38:07.580402 (INFO): Hits right @5: 0.6728515625\n",
      "2021-08-11 01:38:07.580715 (INFO): Hits @5: 0.70751953125\n",
      "2021-08-11 01:38:07.580905 (INFO): Hits left @6: 0.7841796875\n",
      "2021-08-11 01:38:07.581081 (INFO): Hits right @6: 0.720703125\n",
      "2021-08-11 01:38:07.581343 (INFO): Hits @6: 0.75244140625\n",
      "2021-08-11 01:38:07.581746 (INFO): Hits left @7: 0.8115234375\n",
      "2021-08-11 01:38:07.582150 (INFO): Hits right @7: 0.7578125\n",
      "2021-08-11 01:38:07.582457 (INFO): Hits @7: 0.78466796875\n",
      "2021-08-11 01:38:07.582646 (INFO): Hits left @8: 0.837890625\n",
      "2021-08-11 01:38:07.582836 (INFO): Hits right @8: 0.802734375\n",
      "2021-08-11 01:38:07.583110 (INFO): Hits @8: 0.8203125\n",
      "2021-08-11 01:38:07.613306 (INFO): Hits left @9: 0.861328125\n",
      "2021-08-11 01:38:07.613513 (INFO): Hits right @9: 0.841796875\n",
      "2021-08-11 01:38:07.613778 (INFO): Hits @9: 0.8515625\n",
      "2021-08-11 01:38:07.613954 (INFO): Hits left @10: 0.8740234375\n",
      "2021-08-11 01:38:07.614756 (INFO): Hits right @10: 0.8623046875\n",
      "2021-08-11 01:38:07.615031 (INFO): Hits @10: 0.8681640625\n",
      "2021-08-11 01:38:07.615221 (INFO): Mean rank left: 4.8603515625\n",
      "2021-08-11 01:38:07.615385 (INFO): Mean rank right: 5.19140625\n",
      "2021-08-11 01:38:07.615663 (INFO): Mean rank: 5.02587890625\n",
      "2021-08-11 01:38:07.615848 (INFO): Mean reciprocal rank left: 0.5378582394267282\n",
      "2021-08-11 01:38:07.616260 (INFO): Mean reciprocal rank right: 0.4829421195466405\n",
      "2021-08-11 01:38:07.617189 (INFO): Mean reciprocal rank: 0.5104001794866844\n",
      "2021-08-11 01:38:19.255944 (INFO): Total epoch time: 0:00:11\n",
      "2021-08-11 01:38:19.262894 (INFO): \n",
      "\n",
      "2021-08-11 01:38:19.263583 (INFO): ########################################\n",
      "2021-08-11 01:38:19.263677 (INFO):           COMPLETED EPOCH: 18                              \n",
      "2021-08-11 01:38:19.264276 (INFO): train Loss: 0.14387\t99% CI: (0.13496, 0.15278), n=23\n",
      "2021-08-11 01:38:19.264801 (INFO): ########################################\n",
      "2021-08-11 01:38:19.264868 (INFO): \n",
      "\n",
      "2021-08-11 01:38:31.796899 (INFO): Total epoch time: 0:00:12\n",
      "2021-08-11 01:38:31.831989 (INFO): \n",
      "\n",
      "2021-08-11 01:38:31.860222 (INFO): ########################################\n",
      "2021-08-11 01:38:31.956458 (INFO):           COMPLETED EPOCH: 19                              \n",
      "2021-08-11 01:38:32.030145 (INFO): train Loss: 0.13969\t99% CI: (0.12871, 0.15067), n=23\n",
      "2021-08-11 01:38:32.053967 (INFO): ########################################\n",
      "2021-08-11 01:38:32.073109 (INFO): \n",
      "\n",
      "2021-08-11 01:38:32.073314 (INFO): \n",
      "2021-08-11 01:38:32.073368 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:38:32.073407 (INFO): dev_evaluation\n",
      "2021-08-11 01:38:32.073445 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:38:32.073485 (INFO): \n",
      "2021-08-11 01:38:59.627415 (INFO): Hits left @1: 0.41015625\n",
      "2021-08-11 01:38:59.639817 (INFO): Hits right @1: 0.357421875\n",
      "2021-08-11 01:38:59.640111 (INFO): Hits @1: 0.3837890625\n",
      "2021-08-11 01:38:59.640300 (INFO): Hits left @2: 0.5458984375\n",
      "2021-08-11 01:38:59.640474 (INFO): Hits right @2: 0.4658203125\n",
      "2021-08-11 01:38:59.641240 (INFO): Hits @2: 0.505859375\n",
      "2021-08-11 01:38:59.652354 (INFO): Hits left @3: 0.6328125\n",
      "2021-08-11 01:38:59.652982 (INFO): Hits right @3: 0.568359375\n",
      "2021-08-11 01:38:59.653266 (INFO): Hits @3: 0.6005859375\n",
      "2021-08-11 01:38:59.653447 (INFO): Hits left @4: 0.6884765625\n",
      "2021-08-11 01:38:59.653622 (INFO): Hits right @4: 0.626953125\n",
      "2021-08-11 01:38:59.653877 (INFO): Hits @4: 0.65771484375\n",
      "2021-08-11 01:38:59.681854 (INFO): Hits left @5: 0.7392578125\n",
      "2021-08-11 01:38:59.688022 (INFO): Hits right @5: 0.671875\n",
      "2021-08-11 01:38:59.688308 (INFO): Hits @5: 0.70556640625\n",
      "2021-08-11 01:38:59.688488 (INFO): Hits left @6: 0.77734375\n",
      "2021-08-11 01:38:59.688660 (INFO): Hits right @6: 0.712890625\n",
      "2021-08-11 01:38:59.695123 (INFO): Hits @6: 0.7451171875\n",
      "2021-08-11 01:38:59.695371 (INFO): Hits left @7: 0.814453125\n",
      "2021-08-11 01:38:59.695555 (INFO): Hits right @7: 0.7626953125\n",
      "2021-08-11 01:38:59.695815 (INFO): Hits @7: 0.78857421875\n",
      "2021-08-11 01:38:59.695988 (INFO): Hits left @8: 0.8466796875\n",
      "2021-08-11 01:38:59.696157 (INFO): Hits right @8: 0.822265625\n",
      "2021-08-11 01:38:59.696411 (INFO): Hits @8: 0.83447265625\n",
      "2021-08-11 01:38:59.696584 (INFO): Hits left @9: 0.8681640625\n",
      "2021-08-11 01:38:59.697551 (INFO): Hits right @9: 0.859375\n",
      "2021-08-11 01:38:59.697829 (INFO): Hits @9: 0.86376953125\n",
      "2021-08-11 01:38:59.698008 (INFO): Hits left @10: 0.8916015625\n",
      "2021-08-11 01:38:59.698598 (INFO): Hits right @10: 0.8896484375\n",
      "2021-08-11 01:38:59.698876 (INFO): Hits @10: 0.890625\n",
      "2021-08-11 01:38:59.699065 (INFO): Mean rank left: 4.6162109375\n",
      "2021-08-11 01:38:59.699231 (INFO): Mean rank right: 5.15625\n",
      "2021-08-11 01:38:59.699455 (INFO): Mean rank: 4.88623046875\n",
      "2021-08-11 01:38:59.699696 (INFO): Mean reciprocal rank left: 0.5587264847236282\n",
      "2021-08-11 01:38:59.699880 (INFO): Mean reciprocal rank right: 0.5050842923623693\n",
      "2021-08-11 01:38:59.700125 (INFO): Mean reciprocal rank: 0.5319053885429986\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 01:38:59.730965 (INFO): \n",
      "2021-08-11 01:38:59.731532 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:38:59.731589 (INFO): test_evaluation\n",
      "2021-08-11 01:38:59.731628 (INFO): --------------------------------------------------\n",
      "2021-08-11 01:38:59.731664 (INFO): \n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 01:39:36.787769 (INFO): Hits left @1: 0.3818359375\n",
      "2021-08-11 01:39:36.788430 (INFO): Hits right @1: 0.3310546875\n",
      "2021-08-11 01:39:36.788593 (INFO): Hits @1: 0.3564453125\n",
      "2021-08-11 01:39:36.788698 (INFO): Hits left @2: 0.5361328125\n",
      "2021-08-11 01:39:36.788798 (INFO): Hits right @2: 0.43359375\n",
      "2021-08-11 01:39:36.788981 (INFO): Hits @2: 0.48486328125\n",
      "2021-08-11 01:39:36.789076 (INFO): Hits left @3: 0.626953125\n",
      "2021-08-11 01:39:36.789168 (INFO): Hits right @3: 0.5400390625\n",
      "2021-08-11 01:39:36.789372 (INFO): Hits @3: 0.58349609375\n",
      "2021-08-11 01:39:36.789467 (INFO): Hits left @4: 0.6904296875\n",
      "2021-08-11 01:39:36.789560 (INFO): Hits right @4: 0.609375\n",
      "2021-08-11 01:39:36.789737 (INFO): Hits @4: 0.64990234375\n",
      "2021-08-11 01:39:36.789830 (INFO): Hits left @5: 0.748046875\n",
      "2021-08-11 01:39:36.789925 (INFO): Hits right @5: 0.67578125\n",
      "2021-08-11 01:39:36.790063 (INFO): Hits @5: 0.7119140625\n",
      "2021-08-11 01:39:36.790155 (INFO): Hits left @6: 0.7880859375\n",
      "2021-08-11 01:39:36.790247 (INFO): Hits right @6: 0.7041015625\n",
      "2021-08-11 01:39:36.790384 (INFO): Hits @6: 0.74609375\n",
      "2021-08-11 01:39:36.790516 (INFO): Hits left @7: 0.828125\n",
      "2021-08-11 01:39:36.790933 (INFO): Hits right @7: 0.75\n",
      "2021-08-11 01:39:36.791115 (INFO): Hits @7: 0.7890625\n",
      "2021-08-11 01:39:36.791249 (INFO): Hits left @8: 0.8505859375\n",
      "2021-08-11 01:39:36.791343 (INFO): Hits right @8: 0.796875\n",
      "2021-08-11 01:39:36.791522 (INFO): Hits @8: 0.82373046875\n",
      "2021-08-11 01:39:36.791637 (INFO): Hits left @9: 0.8740234375\n",
      "2021-08-11 01:39:36.791736 (INFO): Hits right @9: 0.8369140625\n",
      "2021-08-11 01:39:36.791881 (INFO): Hits @9: 0.85546875\n",
      "2021-08-11 01:39:36.792218 (INFO): Hits left @10: 0.8896484375\n",
      "2021-08-11 01:39:36.792331 (INFO): Hits right @10: 0.8701171875\n",
      "2021-08-11 01:39:36.792482 (INFO): Hits @10: 0.8798828125\n",
      "2021-08-11 01:39:36.792604 (INFO): Mean rank left: 4.73046875\n",
      "2021-08-11 01:39:36.810640 (INFO): Mean rank right: 5.22265625\n",
      "2021-08-11 01:39:36.811031 (INFO): Mean rank: 4.9765625\n",
      "2021-08-11 01:39:36.811152 (INFO): Mean reciprocal rank left: 0.5429804439496646\n",
      "2021-08-11 01:39:36.811261 (INFO): Mean reciprocal rank right: 0.4822130822900962\n",
      "2021-08-11 01:39:36.811401 (INFO): Mean reciprocal rank: 0.5125967631198804\n",
      "2021-08-11 01:39:51.126409 (INFO): Total epoch time: 0:00:14\n",
      "2021-08-11 01:40:08.373524 (INFO): \n",
      "\n",
      "2021-08-11 01:40:08.404872 (INFO): ########################################\n",
      "2021-08-11 01:40:08.404939 (INFO):           COMPLETED EPOCH: 20                              \n",
      "2021-08-11 01:40:08.405349 (INFO): train Loss: 0.13396\t99% CI: (0.12217, 0.14574), n=23\n",
      "2021-08-11 01:40:08.405391 (INFO): ########################################\n",
      "2021-08-11 01:40:08.405426 (INFO): \n",
      "\n",
      "2021-08-11 02:10:20.925351 (INFO): Total epoch time: 0:30:12\n",
      "2021-08-11 02:10:20.926849 (INFO): \n",
      "\n",
      "2021-08-11 02:10:20.927230 (INFO): ########################################\n",
      "2021-08-11 02:10:20.927288 (INFO):           COMPLETED EPOCH: 21                              \n",
      "2021-08-11 02:10:20.927330 (INFO): train Loss: 0.1353\t99% CI: (0.12381, 0.14678), n=23\n",
      "2021-08-11 02:10:20.927384 (INFO): ########################################\n",
      "2021-08-11 02:10:20.927437 (INFO): \n",
      "\n",
      "2021-08-11 02:10:20.927607 (INFO): \n",
      "2021-08-11 02:10:20.927655 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:10:20.927705 (INFO): dev_evaluation\n",
      "2021-08-11 02:10:20.927729 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:10:20.927751 (INFO): \n",
      "2021-08-11 02:10:53.510127 (INFO): Hits left @1: 0.4140625\n",
      "2021-08-11 02:10:53.531150 (INFO): Hits right @1: 0.357421875\n",
      "2021-08-11 02:10:53.570414 (INFO): Hits @1: 0.3857421875\n",
      "2021-08-11 02:10:53.571242 (INFO): Hits left @2: 0.5576171875\n",
      "2021-08-11 02:10:53.571822 (INFO): Hits right @2: 0.4755859375\n",
      "2021-08-11 02:10:53.572821 (INFO): Hits @2: 0.5166015625\n",
      "2021-08-11 02:10:53.573369 (INFO): Hits left @3: 0.630859375\n",
      "2021-08-11 02:10:53.581227 (INFO): Hits right @3: 0.564453125\n",
      "2021-08-11 02:10:53.582044 (INFO): Hits @3: 0.59765625\n",
      "2021-08-11 02:10:53.612428 (INFO): Hits left @4: 0.6875\n",
      "2021-08-11 02:10:53.613211 (INFO): Hits right @4: 0.62890625\n",
      "2021-08-11 02:10:53.613994 (INFO): Hits @4: 0.658203125\n",
      "2021-08-11 02:10:53.614608 (INFO): Hits left @5: 0.736328125\n",
      "2021-08-11 02:10:53.615108 (INFO): Hits right @5: 0.6875\n",
      "2021-08-11 02:10:53.615833 (INFO): Hits @5: 0.7119140625\n",
      "2021-08-11 02:10:53.647608 (INFO): Hits left @6: 0.78125\n",
      "2021-08-11 02:10:53.651991 (INFO): Hits right @6: 0.728515625\n",
      "2021-08-11 02:10:53.656305 (INFO): Hits @6: 0.7548828125\n",
      "2021-08-11 02:10:53.657967 (INFO): Hits left @7: 0.8154296875\n",
      "2021-08-11 02:10:53.658765 (INFO): Hits right @7: 0.7822265625\n",
      "2021-08-11 02:10:53.659569 (INFO): Hits @7: 0.798828125\n",
      "2021-08-11 02:10:53.663150 (INFO): Hits left @8: 0.845703125\n",
      "2021-08-11 02:10:53.665046 (INFO): Hits right @8: 0.8271484375\n",
      "2021-08-11 02:10:53.666061 (INFO): Hits @8: 0.83642578125\n",
      "2021-08-11 02:10:53.666624 (INFO): Hits left @9: 0.8740234375\n",
      "2021-08-11 02:10:53.694845 (INFO): Hits right @9: 0.86328125\n",
      "2021-08-11 02:10:53.696406 (INFO): Hits @9: 0.86865234375\n",
      "2021-08-11 02:10:53.698795 (INFO): Hits left @10: 0.892578125\n",
      "2021-08-11 02:10:53.699508 (INFO): Hits right @10: 0.8876953125\n",
      "2021-08-11 02:10:53.700557 (INFO): Hits @10: 0.89013671875\n",
      "2021-08-11 02:10:53.701130 (INFO): Mean rank left: 4.6142578125\n",
      "2021-08-11 02:10:53.717988 (INFO): Mean rank right: 5.0986328125\n",
      "2021-08-11 02:10:53.741943 (INFO): Mean rank: 4.8564453125\n",
      "2021-08-11 02:10:53.744746 (INFO): Mean reciprocal rank left: 0.5626337683741132\n",
      "2021-08-11 02:10:53.749498 (INFO): Mean reciprocal rank right: 0.5079076606216373\n",
      "2021-08-11 02:10:53.759172 (INFO): Mean reciprocal rank: 0.5352707144978752\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 02:10:53.889136 (INFO): \n",
      "2021-08-11 02:10:53.889572 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:10:53.889738 (INFO): test_evaluation\n",
      "2021-08-11 02:10:53.889873 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:10:53.889990 (INFO): \n",
      "2021-08-11 02:11:29.994113 (INFO): Hits left @1: 0.40625\n",
      "2021-08-11 02:11:29.996076 (INFO): Hits right @1: 0.3330078125\n",
      "2021-08-11 02:11:30.001426 (INFO): Hits @1: 0.36962890625\n",
      "2021-08-11 02:11:30.004805 (INFO): Hits left @2: 0.541015625\n",
      "2021-08-11 02:11:30.007286 (INFO): Hits right @2: 0.4541015625\n",
      "2021-08-11 02:11:30.008675 (INFO): Hits @2: 0.49755859375\n",
      "2021-08-11 02:11:30.012199 (INFO): Hits left @3: 0.626953125\n",
      "2021-08-11 02:11:30.044040 (INFO): Hits right @3: 0.546875\n",
      "2021-08-11 02:11:30.046714 (INFO): Hits @3: 0.5869140625\n",
      "2021-08-11 02:11:30.051204 (INFO): Hits left @4: 0.6962890625\n",
      "2021-08-11 02:11:30.086124 (INFO): Hits right @4: 0.6220703125\n",
      "2021-08-11 02:11:30.098729 (INFO): Hits @4: 0.6591796875\n",
      "2021-08-11 02:11:30.101324 (INFO): Hits left @5: 0.7431640625\n",
      "2021-08-11 02:11:30.102230 (INFO): Hits right @5: 0.6728515625\n",
      "2021-08-11 02:11:30.105355 (INFO): Hits @5: 0.7080078125\n",
      "2021-08-11 02:11:30.106349 (INFO): Hits left @6: 0.8046875\n",
      "2021-08-11 02:11:30.107429 (INFO): Hits right @6: 0.7158203125\n",
      "2021-08-11 02:11:30.112818 (INFO): Hits @6: 0.76025390625\n",
      "2021-08-11 02:11:30.116775 (INFO): Hits left @7: 0.833984375\n",
      "2021-08-11 02:11:30.118860 (INFO): Hits right @7: 0.75390625\n",
      "2021-08-11 02:11:30.124389 (INFO): Hits @7: 0.7939453125\n",
      "2021-08-11 02:11:30.126338 (INFO): Hits left @8: 0.853515625\n",
      "2021-08-11 02:11:30.128496 (INFO): Hits right @8: 0.7958984375\n",
      "2021-08-11 02:11:30.130765 (INFO): Hits @8: 0.82470703125\n",
      "2021-08-11 02:11:30.134830 (INFO): Hits left @9: 0.87890625\n",
      "2021-08-11 02:11:30.138208 (INFO): Hits right @9: 0.8515625\n",
      "2021-08-11 02:11:30.140667 (INFO): Hits @9: 0.865234375\n",
      "2021-08-11 02:11:30.145931 (INFO): Hits left @10: 0.8916015625\n",
      "2021-08-11 02:11:30.152075 (INFO): Hits right @10: 0.8798828125\n",
      "2021-08-11 02:11:30.224523 (INFO): Hits @10: 0.8857421875\n",
      "2021-08-11 02:11:30.233211 (INFO): Mean rank left: 4.7080078125\n",
      "2021-08-11 02:11:30.234057 (INFO): Mean rank right: 5.111328125\n",
      "2021-08-11 02:11:30.239477 (INFO): Mean rank: 4.90966796875\n",
      "2021-08-11 02:11:30.245635 (INFO): Mean reciprocal rank left: 0.5567188762779707\n",
      "2021-08-11 02:11:30.254529 (INFO): Mean reciprocal rank right: 0.48847544569461004\n",
      "2021-08-11 02:11:30.301770 (INFO): Mean reciprocal rank: 0.5225971609862904\n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 02:11:44.968123 (INFO): Total epoch time: 0:00:14\n",
      "2021-08-11 02:11:45.009792 (INFO): \n",
      "\n",
      "2021-08-11 02:11:45.011155 (INFO): ########################################\n",
      "2021-08-11 02:11:45.064345 (INFO):           COMPLETED EPOCH: 22                              \n",
      "2021-08-11 02:11:45.064579 (INFO): train Loss: 0.14223\t99% CI: (0.12947, 0.15499), n=23\n",
      "2021-08-11 02:11:45.064747 (INFO): ########################################\n",
      "2021-08-11 02:11:45.064903 (INFO): \n",
      "\n",
      "2021-08-11 02:31:53.113447 (INFO): Total epoch time: 0:20:08\n",
      "2021-08-11 02:31:53.122438 (INFO): \n",
      "\n",
      "2021-08-11 02:31:53.122907 (INFO): ########################################\n",
      "2021-08-11 02:31:53.123155 (INFO):           COMPLETED EPOCH: 23                              \n",
      "2021-08-11 02:31:53.123372 (INFO): train Loss: 0.1418\t99% CI: (0.13059, 0.15301), n=23\n",
      "2021-08-11 02:31:53.123582 (INFO): ########################################\n",
      "2021-08-11 02:31:53.123767 (INFO): \n",
      "\n",
      "2021-08-11 02:31:53.134157 (INFO): \n",
      "2021-08-11 02:31:53.135478 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:31:53.136784 (INFO): dev_evaluation\n",
      "2021-08-11 02:31:53.145984 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:31:53.147475 (INFO): \n",
      "2021-08-11 02:32:33.858707 (INFO): Hits left @1: 0.4306640625\n",
      "2021-08-11 02:32:33.915960 (INFO): Hits right @1: 0.369140625\n",
      "2021-08-11 02:32:33.921068 (INFO): Hits @1: 0.39990234375\n",
      "2021-08-11 02:32:33.925612 (INFO): Hits left @2: 0.5654296875\n",
      "2021-08-11 02:32:33.929889 (INFO): Hits right @2: 0.4814453125\n",
      "2021-08-11 02:32:33.933436 (INFO): Hits @2: 0.5234375\n",
      "2021-08-11 02:32:33.943088 (INFO): Hits left @3: 0.6513671875\n",
      "2021-08-11 02:32:33.944429 (INFO): Hits right @3: 0.5712890625\n",
      "2021-08-11 02:32:33.978018 (INFO): Hits @3: 0.611328125\n",
      "2021-08-11 02:32:33.978745 (INFO): Hits left @4: 0.7060546875\n",
      "2021-08-11 02:32:33.979273 (INFO): Hits right @4: 0.6435546875\n",
      "2021-08-11 02:32:33.994187 (INFO): Hits @4: 0.6748046875\n",
      "2021-08-11 02:32:34.015791 (INFO): Hits left @5: 0.7568359375\n",
      "2021-08-11 02:32:34.026046 (INFO): Hits right @5: 0.7109375\n",
      "2021-08-11 02:32:34.097984 (INFO): Hits @5: 0.73388671875\n",
      "2021-08-11 02:32:34.099784 (INFO): Hits left @6: 0.7958984375\n",
      "2021-08-11 02:32:34.101335 (INFO): Hits right @6: 0.7587890625\n",
      "2021-08-11 02:32:34.106458 (INFO): Hits @6: 0.77734375\n",
      "2021-08-11 02:32:34.117833 (INFO): Hits left @7: 0.83203125\n",
      "2021-08-11 02:32:34.119736 (INFO): Hits right @7: 0.8046875\n",
      "2021-08-11 02:32:34.164268 (INFO): Hits @7: 0.818359375\n",
      "2021-08-11 02:32:34.197619 (INFO): Hits left @8: 0.8544921875\n",
      "2021-08-11 02:32:34.198450 (INFO): Hits right @8: 0.84765625\n",
      "2021-08-11 02:32:34.199244 (INFO): Hits @8: 0.85107421875\n",
      "2021-08-11 02:32:34.213867 (INFO): Hits left @9: 0.8798828125\n",
      "2021-08-11 02:32:34.250022 (INFO): Hits right @9: 0.8720703125\n",
      "2021-08-11 02:32:34.291333 (INFO): Hits @9: 0.8759765625\n",
      "2021-08-11 02:32:34.361180 (INFO): Hits left @10: 0.9013671875\n",
      "2021-08-11 02:32:34.364151 (INFO): Hits right @10: 0.8828125\n",
      "2021-08-11 02:32:34.366528 (INFO): Hits @10: 0.89208984375\n",
      "2021-08-11 02:32:34.367571 (INFO): Mean rank left: 4.453125\n",
      "2021-08-11 02:32:34.368362 (INFO): Mean rank right: 4.947265625\n",
      "2021-08-11 02:32:34.369963 (INFO): Mean rank: 4.7001953125\n",
      "2021-08-11 02:32:34.371548 (INFO): Mean reciprocal rank left: 0.5764917362148957\n",
      "2021-08-11 02:32:34.395922 (INFO): Mean reciprocal rank right: 0.5182865530469092\n",
      "2021-08-11 02:32:34.397021 (INFO): Mean reciprocal rank: 0.5473891446309024\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 02:32:34.552805 (INFO): \n",
      "2021-08-11 02:32:34.554038 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:32:34.555510 (INFO): test_evaluation\n",
      "2021-08-11 02:32:34.557284 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:32:34.557534 (INFO): \n",
      "2021-08-11 02:48:30.544630 (INFO): Hits left @1: 0.4140625\n",
      "2021-08-11 02:48:30.548726 (INFO): Hits right @1: 0.3330078125\n",
      "2021-08-11 02:48:30.549704 (INFO): Hits @1: 0.37353515625\n",
      "2021-08-11 02:48:30.554155 (INFO): Hits left @2: 0.5615234375\n",
      "2021-08-11 02:48:30.556126 (INFO): Hits right @2: 0.458984375\n",
      "2021-08-11 02:48:30.558318 (INFO): Hits @2: 0.51025390625\n",
      "2021-08-11 02:48:30.563096 (INFO): Hits left @3: 0.6376953125\n",
      "2021-08-11 02:48:30.564923 (INFO): Hits right @3: 0.568359375\n",
      "2021-08-11 02:48:30.580484 (INFO): Hits @3: 0.60302734375\n",
      "2021-08-11 02:48:30.582290 (INFO): Hits left @4: 0.6982421875\n",
      "2021-08-11 02:48:30.583070 (INFO): Hits right @4: 0.6201171875\n",
      "2021-08-11 02:48:30.584076 (INFO): Hits @4: 0.6591796875\n",
      "2021-08-11 02:48:30.587544 (INFO): Hits left @5: 0.7470703125\n",
      "2021-08-11 02:48:30.589356 (INFO): Hits right @5: 0.6865234375\n",
      "2021-08-11 02:48:30.591476 (INFO): Hits @5: 0.716796875\n",
      "2021-08-11 02:48:30.593240 (INFO): Hits left @6: 0.8046875\n",
      "2021-08-11 02:48:30.595028 (INFO): Hits right @6: 0.73046875\n",
      "2021-08-11 02:48:30.597135 (INFO): Hits @6: 0.767578125\n",
      "2021-08-11 02:48:30.600577 (INFO): Hits left @7: 0.845703125\n",
      "2021-08-11 02:48:30.602625 (INFO): Hits right @7: 0.76953125\n",
      "2021-08-11 02:48:30.612317 (INFO): Hits @7: 0.8076171875\n",
      "2021-08-11 02:48:30.640851 (INFO): Hits left @8: 0.857421875\n",
      "2021-08-11 02:48:30.641754 (INFO): Hits right @8: 0.8203125\n",
      "2021-08-11 02:48:30.646679 (INFO): Hits @8: 0.8388671875\n",
      "2021-08-11 02:48:30.658006 (INFO): Hits left @9: 0.884765625\n",
      "2021-08-11 02:48:30.658974 (INFO): Hits right @9: 0.8623046875\n",
      "2021-08-11 02:48:30.663185 (INFO): Hits @9: 0.87353515625\n",
      "2021-08-11 02:48:30.668441 (INFO): Hits left @10: 0.8994140625\n",
      "2021-08-11 02:48:30.671053 (INFO): Hits right @10: 0.888671875\n",
      "2021-08-11 02:48:30.672401 (INFO): Hits @10: 0.89404296875\n",
      "2021-08-11 02:48:30.675801 (INFO): Mean rank left: 4.625\n",
      "2021-08-11 02:48:30.680399 (INFO): Mean rank right: 5.01953125\n",
      "2021-08-11 02:48:30.732311 (INFO): Mean rank: 4.822265625\n",
      "2021-08-11 02:48:30.753281 (INFO): Mean reciprocal rank left: 0.5655636588376246\n",
      "2021-08-11 02:48:30.755089 (INFO): Mean reciprocal rank right: 0.4927111171477092\n",
      "2021-08-11 02:48:30.758176 (INFO): Mean reciprocal rank: 0.5291373879926669\n",
      "2021-08-11 02:48:45.213198 (INFO): Total epoch time: 0:00:14\n",
      "2021-08-11 02:48:45.220936 (INFO): \n",
      "\n",
      "2021-08-11 02:48:45.221649 (INFO): ########################################\n",
      "2021-08-11 02:48:45.230637 (INFO):           COMPLETED EPOCH: 24                              \n",
      "2021-08-11 02:48:45.237929 (INFO): train Loss: 0.14123\t99% CI: (0.13012, 0.15234), n=23\n",
      "2021-08-11 02:48:45.238140 (INFO): ########################################\n",
      "2021-08-11 02:48:45.238257 (INFO): \n",
      "\n",
      "2021-08-11 02:49:00.900396 (INFO): Total epoch time: 0:00:15\n",
      "2021-08-11 02:49:00.920929 (INFO): \n",
      "\n",
      "2021-08-11 02:49:00.924143 (INFO): ########################################\n",
      "2021-08-11 02:49:00.924326 (INFO):           COMPLETED EPOCH: 25                              \n",
      "2021-08-11 02:49:00.924440 (INFO): train Loss: 0.13694\t99% CI: (0.12371, 0.15017), n=23\n",
      "2021-08-11 02:49:00.924543 (INFO): ########################################\n",
      "2021-08-11 02:49:00.924644 (INFO): \n",
      "\n",
      "2021-08-11 02:49:00.926030 (INFO): \n",
      "2021-08-11 02:49:00.926286 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:49:00.926410 (INFO): dev_evaluation\n",
      "2021-08-11 02:49:00.926519 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:49:00.926620 (INFO): \n",
      "2021-08-11 02:49:40.697160 (INFO): Hits left @1: 0.4228515625\n",
      "2021-08-11 02:49:40.738107 (INFO): Hits right @1: 0.365234375\n",
      "2021-08-11 02:49:40.738927 (INFO): Hits @1: 0.39404296875\n",
      "2021-08-11 02:49:40.757516 (INFO): Hits left @2: 0.5712890625\n",
      "2021-08-11 02:49:40.759443 (INFO): Hits right @2: 0.4814453125\n",
      "2021-08-11 02:49:40.764011 (INFO): Hits @2: 0.5263671875\n",
      "2021-08-11 02:49:40.765845 (INFO): Hits left @3: 0.646484375\n",
      "2021-08-11 02:49:40.766848 (INFO): Hits right @3: 0.5732421875\n",
      "2021-08-11 02:49:40.768212 (INFO): Hits @3: 0.60986328125\n",
      "2021-08-11 02:49:40.794534 (INFO): Hits left @4: 0.7021484375\n",
      "2021-08-11 02:49:40.798115 (INFO): Hits right @4: 0.6455078125\n",
      "2021-08-11 02:49:40.800154 (INFO): Hits @4: 0.673828125\n",
      "2021-08-11 02:49:40.801960 (INFO): Hits left @5: 0.7568359375\n",
      "2021-08-11 02:49:40.805770 (INFO): Hits right @5: 0.7041015625\n",
      "2021-08-11 02:49:40.810202 (INFO): Hits @5: 0.73046875\n",
      "2021-08-11 02:49:40.811927 (INFO): Hits left @6: 0.796875\n",
      "2021-08-11 02:49:40.815600 (INFO): Hits right @6: 0.7509765625\n",
      "2021-08-11 02:49:40.871827 (INFO): Hits @6: 0.77392578125\n",
      "2021-08-11 02:49:40.872564 (INFO): Hits left @7: 0.8271484375\n",
      "2021-08-11 02:49:40.873380 (INFO): Hits right @7: 0.794921875\n",
      "2021-08-11 02:49:40.878451 (INFO): Hits @7: 0.81103515625\n",
      "2021-08-11 02:49:40.881485 (INFO): Hits left @8: 0.8544921875\n",
      "2021-08-11 02:49:40.895541 (INFO): Hits right @8: 0.830078125\n",
      "2021-08-11 02:49:40.897008 (INFO): Hits @8: 0.84228515625\n",
      "2021-08-11 02:49:40.897758 (INFO): Hits left @9: 0.87890625\n",
      "2021-08-11 02:49:40.898339 (INFO): Hits right @9: 0.8642578125\n",
      "2021-08-11 02:49:40.901754 (INFO): Hits @9: 0.87158203125\n",
      "2021-08-11 02:49:40.905981 (INFO): Hits left @10: 0.90234375\n",
      "2021-08-11 02:49:40.939795 (INFO): Hits right @10: 0.8974609375\n",
      "2021-08-11 02:49:40.953006 (INFO): Hits @10: 0.89990234375\n",
      "2021-08-11 02:49:40.954789 (INFO): Mean rank left: 4.4658203125\n",
      "2021-08-11 02:49:40.956705 (INFO): Mean rank right: 4.9580078125\n",
      "2021-08-11 02:49:40.958423 (INFO): Mean rank: 4.7119140625\n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 02:49:40.984821 (INFO): Mean reciprocal rank left: 0.5728905767918608\n",
      "2021-08-11 02:49:40.985617 (INFO): Mean reciprocal rank right: 0.5159466849781725\n",
      "2021-08-11 02:49:40.986392 (INFO): Mean reciprocal rank: 0.5444186308850167\n",
      "2021-08-11 02:49:40.988594 (INFO): \n",
      "2021-08-11 02:49:41.012611 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:49:41.012878 (INFO): test_evaluation\n",
      "2021-08-11 02:49:41.014058 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:49:41.014250 (INFO): \n",
      "2021-08-11 02:50:17.658033 (INFO): Hits left @1: 0.41796875\n",
      "2021-08-11 02:50:17.659926 (INFO): Hits right @1: 0.3310546875\n",
      "2021-08-11 02:50:17.661896 (INFO): Hits @1: 0.37451171875\n",
      "2021-08-11 02:50:17.665422 (INFO): Hits left @2: 0.556640625\n",
      "2021-08-11 02:50:17.706757 (INFO): Hits right @2: 0.4658203125\n",
      "2021-08-11 02:50:17.722756 (INFO): Hits @2: 0.51123046875\n",
      "2021-08-11 02:50:17.744838 (INFO): Hits left @3: 0.640625\n",
      "2021-08-11 02:50:17.751546 (INFO): Hits right @3: 0.564453125\n",
      "2021-08-11 02:50:17.752318 (INFO): Hits @3: 0.6025390625\n",
      "2021-08-11 02:50:17.756592 (INFO): Hits left @4: 0.712890625\n",
      "2021-08-11 02:50:17.758064 (INFO): Hits right @4: 0.62109375\n",
      "2021-08-11 02:50:17.778402 (INFO): Hits @4: 0.6669921875\n",
      "2021-08-11 02:50:17.804469 (INFO): Hits left @5: 0.7666015625\n",
      "2021-08-11 02:50:17.805035 (INFO): Hits right @5: 0.6865234375\n",
      "2021-08-11 02:50:17.805797 (INFO): Hits @5: 0.7265625\n",
      "2021-08-11 02:50:17.814887 (INFO): Hits left @6: 0.7998046875\n",
      "2021-08-11 02:50:17.875008 (INFO): Hits right @6: 0.734375\n",
      "2021-08-11 02:50:17.940432 (INFO): Hits @6: 0.76708984375\n",
      "2021-08-11 02:50:17.976395 (INFO): Hits left @7: 0.8369140625\n",
      "2021-08-11 02:50:17.980772 (INFO): Hits right @7: 0.7822265625\n",
      "2021-08-11 02:50:17.991245 (INFO): Hits @7: 0.8095703125\n",
      "2021-08-11 02:50:17.992884 (INFO): Hits left @8: 0.8564453125\n",
      "2021-08-11 02:50:17.994744 (INFO): Hits right @8: 0.8212890625\n",
      "2021-08-11 02:50:17.995821 (INFO): Hits @8: 0.8388671875\n",
      "2021-08-11 02:50:17.996422 (INFO): Hits left @9: 0.8837890625\n",
      "2021-08-11 02:50:17.997095 (INFO): Hits right @9: 0.86328125\n",
      "2021-08-11 02:50:17.998048 (INFO): Hits @9: 0.87353515625\n",
      "2021-08-11 02:50:17.998800 (INFO): Hits left @10: 0.896484375\n",
      "2021-08-11 02:50:17.999377 (INFO): Hits right @10: 0.89453125\n",
      "2021-08-11 02:50:18.000292 (INFO): Hits @10: 0.8955078125\n",
      "2021-08-11 02:50:18.000988 (INFO): Mean rank left: 4.5966796875\n",
      "2021-08-11 02:50:18.007357 (INFO): Mean rank right: 4.9638671875\n",
      "2021-08-11 02:50:18.017195 (INFO): Mean rank: 4.7802734375\n",
      "2021-08-11 02:50:18.019794 (INFO): Mean reciprocal rank left: 0.5680870496285626\n",
      "2021-08-11 02:50:18.020349 (INFO): Mean reciprocal rank right: 0.4931118748046105\n",
      "2021-08-11 02:50:18.021711 (INFO): Mean reciprocal rank: 0.5305994622165866\n",
      "2021-08-11 02:50:32.255014 (INFO): Total epoch time: 0:00:14\n",
      "2021-08-11 02:50:32.262247 (INFO): \n",
      "\n",
      "2021-08-11 02:50:32.265951 (INFO): ########################################\n",
      "2021-08-11 02:50:32.266510 (INFO):           COMPLETED EPOCH: 26                              \n",
      "2021-08-11 02:50:32.266754 (INFO): train Loss: 0.14565\t99% CI: (0.13756, 0.15374), n=23\n",
      "2021-08-11 02:50:32.266898 (INFO): ########################################\n",
      "2021-08-11 02:50:32.267041 (INFO): \n",
      "\n",
      "2021-08-11 02:50:47.479444 (INFO): Total epoch time: 0:00:15\n",
      "2021-08-11 02:50:47.482468 (INFO): \n",
      "\n",
      "2021-08-11 02:50:47.483853 (INFO): ########################################\n",
      "2021-08-11 02:50:47.485211 (INFO):           COMPLETED EPOCH: 27                              \n",
      "2021-08-11 02:50:47.486400 (INFO): train Loss: 0.14562\t99% CI: (0.13713, 0.15411), n=23\n",
      "2021-08-11 02:50:47.486609 (INFO): ########################################\n",
      "2021-08-11 02:50:47.487691 (INFO): \n",
      "\n",
      "2021-08-11 02:50:47.488477 (INFO): \n",
      "2021-08-11 02:50:47.489746 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:50:47.489929 (INFO): dev_evaluation\n",
      "2021-08-11 02:50:47.492389 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:50:47.492633 (INFO): \n",
      "2021-08-11 02:51:25.448495 (INFO): Hits left @1: 0.4228515625\n",
      "2021-08-11 02:51:25.452320 (INFO): Hits right @1: 0.3828125\n",
      "2021-08-11 02:51:25.456690 (INFO): Hits @1: 0.40283203125\n",
      "2021-08-11 02:51:25.458809 (INFO): Hits left @2: 0.5673828125\n",
      "2021-08-11 02:51:25.486041 (INFO): Hits right @2: 0.482421875\n",
      "2021-08-11 02:51:25.488210 (INFO): Hits @2: 0.52490234375\n",
      "2021-08-11 02:51:25.498477 (INFO): Hits left @3: 0.6513671875\n",
      "2021-08-11 02:51:25.500480 (INFO): Hits right @3: 0.56640625\n",
      "2021-08-11 02:51:25.501802 (INFO): Hits @3: 0.60888671875\n",
      "2021-08-11 02:51:25.503556 (INFO): Hits left @4: 0.7099609375\n",
      "2021-08-11 02:51:25.513438 (INFO): Hits right @4: 0.646484375\n",
      "2021-08-11 02:51:25.569310 (INFO): Hits @4: 0.67822265625\n",
      "2021-08-11 02:51:25.577880 (INFO): Hits left @5: 0.7626953125\n",
      "2021-08-11 02:51:25.578580 (INFO): Hits right @5: 0.708984375\n",
      "2021-08-11 02:51:25.579359 (INFO): Hits @5: 0.73583984375\n",
      "2021-08-11 02:51:25.586205 (INFO): Hits left @6: 0.7978515625\n",
      "2021-08-11 02:51:25.589537 (INFO): Hits right @6: 0.751953125\n",
      "2021-08-11 02:51:25.590934 (INFO): Hits @6: 0.77490234375\n",
      "2021-08-11 02:51:25.592050 (INFO): Hits left @7: 0.828125\n",
      "2021-08-11 02:51:25.592978 (INFO): Hits right @7: 0.802734375\n",
      "2021-08-11 02:51:25.595853 (INFO): Hits @7: 0.8154296875\n",
      "2021-08-11 02:51:25.596497 (INFO): Hits left @8: 0.85546875\n",
      "2021-08-11 02:51:25.604552 (INFO): Hits right @8: 0.8388671875\n",
      "2021-08-11 02:51:25.610294 (INFO): Hits @8: 0.84716796875\n",
      "2021-08-11 02:51:25.613957 (INFO): Hits left @9: 0.875\n",
      "2021-08-11 02:51:25.615708 (INFO): Hits right @9: 0.873046875\n",
      "2021-08-11 02:51:25.618137 (INFO): Hits @9: 0.8740234375\n",
      "2021-08-11 02:51:25.622237 (INFO): Hits left @10: 0.888671875\n",
      "2021-08-11 02:51:25.626377 (INFO): Hits right @10: 0.8935546875\n",
      "2021-08-11 02:51:25.630879 (INFO): Hits @10: 0.89111328125\n",
      "2021-08-11 02:51:25.634478 (INFO): Mean rank left: 4.5419921875\n",
      "2021-08-11 02:51:25.635470 (INFO): Mean rank right: 4.93359375\n",
      "2021-08-11 02:51:25.636540 (INFO): Mean rank: 4.73779296875\n",
      "2021-08-11 02:51:25.639630 (INFO): Mean reciprocal rank left: 0.5728639044315385\n",
      "2021-08-11 02:51:25.642466 (INFO): Mean reciprocal rank right: 0.524907236255749\n",
      "2021-08-11 02:51:25.645663 (INFO): Mean reciprocal rank: 0.5488855703436437\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 02:51:25.792831 (INFO): \n",
      "2021-08-11 02:51:25.817481 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:51:25.820796 (INFO): test_evaluation\n",
      "2021-08-11 02:51:25.848916 (INFO): --------------------------------------------------\n",
      "2021-08-11 02:51:25.849188 (INFO): \n",
      "2021-08-11 02:52:06.291419 (INFO): Hits left @1: 0.4365234375\n",
      "2021-08-11 02:52:06.292793 (INFO): Hits right @1: 0.3486328125\n",
      "2021-08-11 02:52:06.295196 (INFO): Hits @1: 0.392578125\n",
      "2021-08-11 02:52:06.295832 (INFO): Hits left @2: 0.5693359375\n",
      "2021-08-11 02:52:06.297378 (INFO): Hits right @2: 0.47265625\n",
      "2021-08-11 02:52:06.299255 (INFO): Hits @2: 0.52099609375\n",
      "2021-08-11 02:52:06.301013 (INFO): Hits left @3: 0.65234375\n",
      "2021-08-11 02:52:06.302551 (INFO): Hits right @3: 0.5703125\n",
      "2021-08-11 02:52:06.304462 (INFO): Hits @3: 0.611328125\n",
      "2021-08-11 02:52:06.308501 (INFO): Hits left @4: 0.7138671875\n",
      "2021-08-11 02:52:06.311830 (INFO): Hits right @4: 0.6357421875\n",
      "2021-08-11 02:52:06.327349 (INFO): Hits @4: 0.6748046875\n",
      "2021-08-11 02:52:06.328360 (INFO): Hits left @5: 0.755859375\n",
      "2021-08-11 02:52:06.329073 (INFO): Hits right @5: 0.6767578125\n",
      "2021-08-11 02:52:06.331176 (INFO): Hits @5: 0.71630859375\n",
      "2021-08-11 02:52:06.334020 (INFO): Hits left @6: 0.80859375\n",
      "2021-08-11 02:52:06.348176 (INFO): Hits right @6: 0.7265625\n",
      "2021-08-11 02:52:06.348944 (INFO): Hits @6: 0.767578125\n",
      "2021-08-11 02:52:06.349388 (INFO): Hits left @7: 0.8408203125\n",
      "2021-08-11 02:52:06.349991 (INFO): Hits right @7: 0.78125\n",
      "2021-08-11 02:52:06.352087 (INFO): Hits @7: 0.81103515625\n",
      "2021-08-11 02:52:06.355236 (INFO): Hits left @8: 0.859375\n",
      "2021-08-11 02:52:06.358302 (INFO): Hits right @8: 0.818359375\n",
      "2021-08-11 02:52:06.376830 (INFO): Hits @8: 0.8388671875\n",
      "2021-08-11 02:52:06.378744 (INFO): Hits left @9: 0.8798828125\n",
      "2021-08-11 02:52:06.379774 (INFO): Hits right @9: 0.859375\n",
      "2021-08-11 02:52:06.380519 (INFO): Hits @9: 0.86962890625\n",
      "2021-08-11 02:52:06.382461 (INFO): Hits left @10: 0.8935546875\n",
      "2021-08-11 02:52:06.384372 (INFO): Hits right @10: 0.884765625\n",
      "2021-08-11 02:52:06.393841 (INFO): Hits @10: 0.88916015625\n",
      "2021-08-11 02:52:06.427798 (INFO): Mean rank left: 4.5830078125\n",
      "2021-08-11 02:52:06.428853 (INFO): Mean rank right: 4.970703125\n",
      "2021-08-11 02:52:06.429688 (INFO): Mean rank: 4.77685546875\n",
      "2021-08-11 02:52:06.430547 (INFO): Mean reciprocal rank left: 0.580272849714117\n",
      "2021-08-11 02:52:06.431149 (INFO): Mean reciprocal rank right: 0.503515437337896\n",
      "2021-08-11 02:52:06.434310 (INFO): Mean reciprocal rank: 0.5418941435260065\n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 03:22:14.393558 (INFO): Total epoch time: 0:30:07\n",
      "2021-08-11 03:22:14.477694 (INFO): \n",
      "\n",
      "2021-08-11 03:22:14.493182 (INFO): ########################################\n",
      "2021-08-11 03:22:14.493455 (INFO):           COMPLETED EPOCH: 28                              \n",
      "2021-08-11 03:22:14.493522 (INFO): train Loss: 0.1309\t99% CI: (0.11752, 0.14428), n=23\n",
      "2021-08-11 03:22:14.528898 (INFO): ########################################\n",
      "2021-08-11 03:22:14.542153 (INFO): \n",
      "\n",
      "2021-08-11 03:22:32.128765 (INFO): Total epoch time: 0:00:17\n",
      "2021-08-11 03:22:32.131565 (INFO): \n",
      "\n",
      "2021-08-11 03:22:32.132257 (INFO): ########################################\n",
      "2021-08-11 03:22:32.132407 (INFO):           COMPLETED EPOCH: 29                              \n",
      "2021-08-11 03:22:32.132517 (INFO): train Loss: 0.13851\t99% CI: (0.12575, 0.15128), n=23\n",
      "2021-08-11 03:22:32.132617 (INFO): ########################################\n",
      "2021-08-11 03:22:32.132714 (INFO): \n",
      "\n",
      "2021-08-11 03:22:32.133137 (INFO): \n",
      "2021-08-11 03:22:32.134488 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:22:32.138494 (INFO): dev_evaluation\n",
      "2021-08-11 03:22:32.139413 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:22:32.139572 (INFO): \n",
      "2021-08-11 03:23:15.314245 (INFO): Hits left @1: 0.43359375\n",
      "2021-08-11 03:23:15.316769 (INFO): Hits right @1: 0.380859375\n",
      "2021-08-11 03:23:15.318040 (INFO): Hits @1: 0.4072265625\n",
      "2021-08-11 03:23:15.319868 (INFO): Hits left @2: 0.56640625\n",
      "2021-08-11 03:23:15.323974 (INFO): Hits right @2: 0.4912109375\n",
      "2021-08-11 03:23:15.327938 (INFO): Hits @2: 0.52880859375\n",
      "2021-08-11 03:23:15.329797 (INFO): Hits left @3: 0.6474609375\n",
      "2021-08-11 03:23:15.333473 (INFO): Hits right @3: 0.5810546875\n",
      "2021-08-11 03:23:15.335520 (INFO): Hits @3: 0.6142578125\n",
      "2021-08-11 03:23:15.357350 (INFO): Hits left @4: 0.7109375\n",
      "2021-08-11 03:23:15.382767 (INFO): Hits right @4: 0.6494140625\n",
      "2021-08-11 03:23:15.383935 (INFO): Hits @4: 0.68017578125\n",
      "2021-08-11 03:23:15.387357 (INFO): Hits left @5: 0.759765625\n",
      "2021-08-11 03:23:15.388328 (INFO): Hits right @5: 0.7099609375\n",
      "2021-08-11 03:23:15.389511 (INFO): Hits @5: 0.73486328125\n",
      "2021-08-11 03:23:15.391197 (INFO): Hits left @6: 0.794921875\n",
      "2021-08-11 03:23:15.395196 (INFO): Hits right @6: 0.7587890625\n",
      "2021-08-11 03:23:15.399749 (INFO): Hits @6: 0.77685546875\n",
      "2021-08-11 03:23:15.401553 (INFO): Hits left @7: 0.826171875\n",
      "2021-08-11 03:23:15.411971 (INFO): Hits right @7: 0.798828125\n",
      "2021-08-11 03:23:15.428416 (INFO): Hits @7: 0.8125\n",
      "2021-08-11 03:23:15.430383 (INFO): Hits left @8: 0.8486328125\n",
      "2021-08-11 03:23:15.431293 (INFO): Hits right @8: 0.8408203125\n",
      "2021-08-11 03:23:15.432409 (INFO): Hits @8: 0.8447265625\n",
      "2021-08-11 03:23:15.434329 (INFO): Hits left @9: 0.873046875\n",
      "2021-08-11 03:23:15.436180 (INFO): Hits right @9: 0.8759765625\n",
      "2021-08-11 03:23:15.437485 (INFO): Hits @9: 0.87451171875\n",
      "2021-08-11 03:23:15.439406 (INFO): Hits left @10: 0.890625\n",
      "2021-08-11 03:23:15.441294 (INFO): Hits right @10: 0.90234375\n",
      "2021-08-11 03:23:15.443532 (INFO): Hits @10: 0.896484375\n",
      "2021-08-11 03:23:15.444369 (INFO): Mean rank left: 4.5185546875\n",
      "2021-08-11 03:23:15.445036 (INFO): Mean rank right: 4.8544921875\n",
      "2021-08-11 03:23:15.446126 (INFO): Mean rank: 4.6865234375\n",
      "2021-08-11 03:23:15.447719 (INFO): Mean reciprocal rank left: 0.5775559261012008\n",
      "2021-08-11 03:23:15.451806 (INFO): Mean reciprocal rank right: 0.5272466747870034\n",
      "2021-08-11 03:23:15.454098 (INFO): Mean reciprocal rank: 0.5524013004441021\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 03:23:15.504612 (INFO): \n",
      "2021-08-11 03:23:15.505958 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:23:15.507825 (INFO): test_evaluation\n",
      "2021-08-11 03:23:15.510553 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:23:15.513107 (INFO): \n",
      "2021-08-11 03:23:56.078606 (INFO): Hits left @1: 0.4208984375\n",
      "2021-08-11 03:23:56.096249 (INFO): Hits right @1: 0.349609375\n",
      "2021-08-11 03:23:56.099979 (INFO): Hits @1: 0.38525390625\n",
      "2021-08-11 03:23:56.100731 (INFO): Hits left @2: 0.5546875\n",
      "2021-08-11 03:23:56.101594 (INFO): Hits right @2: 0.482421875\n",
      "2021-08-11 03:23:56.103621 (INFO): Hits @2: 0.5185546875\n",
      "2021-08-11 03:23:56.107680 (INFO): Hits left @3: 0.64453125\n",
      "2021-08-11 03:23:56.109403 (INFO): Hits right @3: 0.5673828125\n",
      "2021-08-11 03:23:56.126068 (INFO): Hits @3: 0.60595703125\n",
      "2021-08-11 03:23:56.129774 (INFO): Hits left @4: 0.7021484375\n",
      "2021-08-11 03:23:56.133708 (INFO): Hits right @4: 0.63671875\n",
      "2021-08-11 03:23:56.137723 (INFO): Hits @4: 0.66943359375\n",
      "2021-08-11 03:23:56.141076 (INFO): Hits left @5: 0.751953125\n",
      "2021-08-11 03:23:56.143182 (INFO): Hits right @5: 0.6953125\n",
      "2021-08-11 03:23:56.148124 (INFO): Hits @5: 0.7236328125\n",
      "2021-08-11 03:23:56.149872 (INFO): Hits left @6: 0.80859375\n",
      "2021-08-11 03:23:56.153220 (INFO): Hits right @6: 0.744140625\n",
      "2021-08-11 03:23:56.155477 (INFO): Hits @6: 0.7763671875\n",
      "2021-08-11 03:23:56.157781 (INFO): Hits left @7: 0.8466796875\n",
      "2021-08-11 03:23:56.158401 (INFO): Hits right @7: 0.78515625\n",
      "2021-08-11 03:23:56.159319 (INFO): Hits @7: 0.81591796875\n",
      "2021-08-11 03:23:56.160156 (INFO): Hits left @8: 0.869140625\n",
      "2021-08-11 03:23:56.175625 (INFO): Hits right @8: 0.8212890625\n",
      "2021-08-11 03:23:56.189320 (INFO): Hits @8: 0.84521484375\n",
      "2021-08-11 03:23:56.191408 (INFO): Hits left @9: 0.884765625\n",
      "2021-08-11 03:23:56.192077 (INFO): Hits right @9: 0.8662109375\n",
      "2021-08-11 03:23:56.193088 (INFO): Hits @9: 0.87548828125\n",
      "2021-08-11 03:23:56.193645 (INFO): Hits left @10: 0.89453125\n",
      "2021-08-11 03:23:56.221934 (INFO): Hits right @10: 0.88671875\n",
      "2021-08-11 03:23:56.223110 (INFO): Hits @10: 0.890625\n",
      "2021-08-11 03:23:56.223731 (INFO): Mean rank left: 4.5732421875\n",
      "2021-08-11 03:23:56.224549 (INFO): Mean rank right: 4.9287109375\n",
      "2021-08-11 03:23:56.225502 (INFO): Mean rank: 4.7509765625\n",
      "2021-08-11 03:23:56.244034 (INFO): Mean reciprocal rank left: 0.5691140797389604\n",
      "2021-08-11 03:23:56.282618 (INFO): Mean reciprocal rank right: 0.5066008885520461\n",
      "2021-08-11 03:23:56.301012 (INFO): Mean reciprocal rank: 0.5378574841455033\n",
      "2021-08-11 03:24:12.261411 (INFO): Total epoch time: 0:00:15\n",
      "2021-08-11 03:24:12.266397 (INFO): \n",
      "\n",
      "2021-08-11 03:24:12.270039 (INFO): ########################################\n",
      "2021-08-11 03:24:12.270962 (INFO):           COMPLETED EPOCH: 30                              \n",
      "2021-08-11 03:24:12.271103 (INFO): train Loss: 0.12829\t99% CI: (0.11641, 0.14017), n=23\n",
      "2021-08-11 03:24:12.271215 (INFO): ########################################\n",
      "2021-08-11 03:24:12.271334 (INFO): \n",
      "\n",
      "2021-08-11 03:24:27.191462 (INFO): Total epoch time: 0:00:14\n",
      "2021-08-11 03:24:27.239701 (INFO): \n",
      "\n",
      "2021-08-11 03:24:27.240757 (INFO): ########################################\n",
      "2021-08-11 03:24:27.240916 (INFO):           COMPLETED EPOCH: 31                              \n",
      "2021-08-11 03:24:27.241025 (INFO): train Loss: 0.13442\t99% CI: (0.12333, 0.1455), n=23\n",
      "2021-08-11 03:24:27.241122 (INFO): ########################################\n",
      "2021-08-11 03:24:27.241311 (INFO): \n",
      "\n",
      "2021-08-11 03:24:27.241752 (INFO): \n",
      "2021-08-11 03:24:27.241885 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:24:27.241992 (INFO): dev_evaluation\n",
      "2021-08-11 03:24:27.242093 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:24:27.299519 (INFO): \n",
      "2021-08-11 03:25:07.610410 (INFO): Hits left @1: 0.4345703125\n",
      "2021-08-11 03:25:07.697287 (INFO): Hits right @1: 0.3759765625\n",
      "2021-08-11 03:25:07.698275 (INFO): Hits @1: 0.4052734375\n",
      "2021-08-11 03:25:07.699140 (INFO): Hits left @2: 0.578125\n",
      "2021-08-11 03:25:07.699731 (INFO): Hits right @2: 0.4833984375\n",
      "2021-08-11 03:25:07.712032 (INFO): Hits @2: 0.53076171875\n",
      "2021-08-11 03:25:07.713039 (INFO): Hits left @3: 0.6611328125\n",
      "2021-08-11 03:25:07.720616 (INFO): Hits right @3: 0.578125\n",
      "2021-08-11 03:25:07.722912 (INFO): Hits @3: 0.61962890625\n",
      "2021-08-11 03:25:07.724938 (INFO): Hits left @4: 0.7109375\n",
      "2021-08-11 03:25:07.756381 (INFO): Hits right @4: 0.654296875\n",
      "2021-08-11 03:25:07.768656 (INFO): Hits @4: 0.6826171875\n",
      "2021-08-11 03:25:07.771155 (INFO): Hits left @5: 0.7607421875\n",
      "2021-08-11 03:25:07.772102 (INFO): Hits right @5: 0.716796875\n",
      "2021-08-11 03:25:07.777065 (INFO): Hits @5: 0.73876953125\n",
      "2021-08-11 03:25:07.781334 (INFO): Hits left @6: 0.7958984375\n",
      "2021-08-11 03:25:07.785064 (INFO): Hits right @6: 0.771484375\n",
      "2021-08-11 03:25:07.787052 (INFO): Hits @6: 0.78369140625\n",
      "2021-08-11 03:25:07.810533 (INFO): Hits left @7: 0.826171875\n",
      "2021-08-11 03:25:07.811302 (INFO): Hits right @7: 0.80859375\n",
      "2021-08-11 03:25:07.812081 (INFO): Hits @7: 0.8173828125\n",
      "2021-08-11 03:25:07.816589 (INFO): Hits left @8: 0.849609375\n",
      "2021-08-11 03:25:07.820338 (INFO): Hits right @8: 0.849609375\n",
      "2021-08-11 03:25:07.823035 (INFO): Hits @8: 0.849609375\n",
      "2021-08-11 03:25:07.826050 (INFO): Hits left @9: 0.8681640625\n",
      "2021-08-11 03:25:07.855080 (INFO): Hits right @9: 0.8837890625\n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 03:25:07.953933 (INFO): Hits @9: 0.8759765625\n",
      "2021-08-11 03:25:07.955824 (INFO): Hits left @10: 0.888671875\n",
      "2021-08-11 03:25:07.956885 (INFO): Hits right @10: 0.9033203125\n",
      "2021-08-11 03:25:07.958166 (INFO): Hits @10: 0.89599609375\n",
      "2021-08-11 03:25:07.960085 (INFO): Mean rank left: 4.482421875\n",
      "2021-08-11 03:25:07.961255 (INFO): Mean rank right: 4.8203125\n",
      "2021-08-11 03:25:07.962456 (INFO): Mean rank: 4.6513671875\n",
      "2021-08-11 03:25:07.967552 (INFO): Mean reciprocal rank left: 0.5812247775873123\n",
      "2021-08-11 03:25:07.974510 (INFO): Mean reciprocal rank right: 0.5244680169569933\n",
      "2021-08-11 03:25:07.978534 (INFO): Mean reciprocal rank: 0.5528463972721528\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 03:25:08.122521 (INFO): \n",
      "2021-08-11 03:25:08.123786 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:25:08.123971 (INFO): test_evaluation\n",
      "2021-08-11 03:25:08.124258 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:25:08.124414 (INFO): \n",
      "2021-08-11 03:25:50.258324 (INFO): Hits left @1: 0.421875\n",
      "2021-08-11 03:25:50.259592 (INFO): Hits right @1: 0.353515625\n",
      "2021-08-11 03:25:50.262898 (INFO): Hits @1: 0.3876953125\n",
      "2021-08-11 03:25:50.264625 (INFO): Hits left @2: 0.5654296875\n",
      "2021-08-11 03:25:50.271228 (INFO): Hits right @2: 0.4814453125\n",
      "2021-08-11 03:25:50.275809 (INFO): Hits @2: 0.5234375\n",
      "2021-08-11 03:25:50.289603 (INFO): Hits left @3: 0.640625\n",
      "2021-08-11 03:25:50.290200 (INFO): Hits right @3: 0.5703125\n",
      "2021-08-11 03:25:50.324302 (INFO): Hits @3: 0.60546875\n",
      "2021-08-11 03:25:50.327784 (INFO): Hits left @4: 0.697265625\n",
      "2021-08-11 03:25:50.331507 (INFO): Hits right @4: 0.6318359375\n",
      "2021-08-11 03:25:50.332544 (INFO): Hits @4: 0.66455078125\n",
      "2021-08-11 03:25:50.333164 (INFO): Hits left @5: 0.7529296875\n",
      "2021-08-11 03:25:50.334971 (INFO): Hits right @5: 0.6904296875\n",
      "2021-08-11 03:25:50.381853 (INFO): Hits @5: 0.7216796875\n",
      "2021-08-11 03:25:50.428448 (INFO): Hits left @6: 0.80078125\n",
      "2021-08-11 03:25:50.429279 (INFO): Hits right @6: 0.7412109375\n",
      "2021-08-11 03:25:50.430075 (INFO): Hits @6: 0.77099609375\n",
      "2021-08-11 03:25:50.446444 (INFO): Hits left @7: 0.841796875\n",
      "2021-08-11 03:25:50.450830 (INFO): Hits right @7: 0.78515625\n",
      "2021-08-11 03:25:50.452662 (INFO): Hits @7: 0.8134765625\n",
      "2021-08-11 03:25:50.453832 (INFO): Hits left @8: 0.8603515625\n",
      "2021-08-11 03:25:50.454379 (INFO): Hits right @8: 0.82421875\n",
      "2021-08-11 03:25:50.472647 (INFO): Hits @8: 0.84228515625\n",
      "2021-08-11 03:25:50.473250 (INFO): Hits left @9: 0.8857421875\n",
      "2021-08-11 03:25:50.475088 (INFO): Hits right @9: 0.8681640625\n",
      "2021-08-11 03:25:50.476713 (INFO): Hits @9: 0.876953125\n",
      "2021-08-11 03:25:50.562133 (INFO): Hits left @10: 0.8974609375\n",
      "2021-08-11 03:25:50.571437 (INFO): Hits right @10: 0.8876953125\n",
      "2021-08-11 03:25:50.574974 (INFO): Hits @10: 0.892578125\n",
      "2021-08-11 03:25:50.580498 (INFO): Mean rank left: 4.607421875\n",
      "2021-08-11 03:25:50.592561 (INFO): Mean rank right: 4.900390625\n",
      "2021-08-11 03:25:50.593523 (INFO): Mean rank: 4.75390625\n",
      "2021-08-11 03:25:50.594080 (INFO): Mean reciprocal rank left: 0.570399068336238\n",
      "2021-08-11 03:25:50.599168 (INFO): Mean reciprocal rank right: 0.5083822709964014\n",
      "2021-08-11 03:25:50.615613 (INFO): Mean reciprocal rank: 0.5393906696663198\n",
      "2021-08-11 03:26:06.254265 (INFO): Total epoch time: 0:00:15\n",
      "2021-08-11 03:26:06.258017 (INFO): \n",
      "\n",
      "2021-08-11 03:26:06.259041 (INFO): ########################################\n",
      "2021-08-11 03:26:06.259186 (INFO):           COMPLETED EPOCH: 32                              \n",
      "2021-08-11 03:26:06.259285 (INFO): train Loss: 0.14456\t99% CI: (0.13462, 0.15449), n=23\n",
      "2021-08-11 03:26:06.259380 (INFO): ########################################\n",
      "2021-08-11 03:26:06.260475 (INFO): \n",
      "\n",
      "2021-08-11 03:26:21.230917 (INFO): Total epoch time: 0:00:14\n",
      "2021-08-11 03:26:21.235043 (INFO): \n",
      "\n",
      "2021-08-11 03:26:21.235353 (INFO): ########################################\n",
      "2021-08-11 03:26:21.235515 (INFO):           COMPLETED EPOCH: 33                              \n",
      "2021-08-11 03:26:21.235648 (INFO): train Loss: 0.14491\t99% CI: (0.13562, 0.1542), n=23\n",
      "2021-08-11 03:26:21.235776 (INFO): ########################################\n",
      "2021-08-11 03:26:21.235910 (INFO): \n",
      "\n",
      "2021-08-11 03:26:21.236457 (INFO): \n",
      "2021-08-11 03:26:21.239073 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:26:21.240332 (INFO): dev_evaluation\n",
      "2021-08-11 03:26:21.240522 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:26:21.283152 (INFO): \n",
      "2021-08-11 03:27:04.402254 (INFO): Hits left @1: 0.4287109375\n",
      "2021-08-11 03:27:04.458215 (INFO): Hits right @1: 0.3935546875\n",
      "2021-08-11 03:27:04.461498 (INFO): Hits @1: 0.4111328125\n",
      "2021-08-11 03:27:04.463364 (INFO): Hits left @2: 0.57421875\n",
      "2021-08-11 03:27:04.465050 (INFO): Hits right @2: 0.4951171875\n",
      "2021-08-11 03:27:04.466180 (INFO): Hits @2: 0.53466796875\n",
      "2021-08-11 03:27:04.466823 (INFO): Hits left @3: 0.658203125\n",
      "2021-08-11 03:27:04.470268 (INFO): Hits right @3: 0.5869140625\n",
      "2021-08-11 03:27:04.472176 (INFO): Hits @3: 0.62255859375\n",
      "2021-08-11 03:27:04.477307 (INFO): Hits left @4: 0.712890625\n",
      "2021-08-11 03:27:04.478931 (INFO): Hits right @4: 0.6494140625\n",
      "2021-08-11 03:27:04.479787 (INFO): Hits @4: 0.68115234375\n",
      "2021-08-11 03:27:04.480332 (INFO): Hits left @5: 0.76171875\n",
      "2021-08-11 03:27:04.481812 (INFO): Hits right @5: 0.7099609375\n",
      "2021-08-11 03:27:04.490951 (INFO): Hits @5: 0.73583984375\n",
      "2021-08-11 03:27:04.494019 (INFO): Hits left @6: 0.8017578125\n",
      "2021-08-11 03:27:04.495708 (INFO): Hits right @6: 0.767578125\n",
      "2021-08-11 03:27:04.497528 (INFO): Hits @6: 0.78466796875\n",
      "2021-08-11 03:27:04.499241 (INFO): Hits left @7: 0.826171875\n",
      "2021-08-11 03:27:04.500827 (INFO): Hits right @7: 0.8095703125\n",
      "2021-08-11 03:27:04.502721 (INFO): Hits @7: 0.81787109375\n",
      "2021-08-11 03:27:04.504372 (INFO): Hits left @8: 0.85546875\n",
      "2021-08-11 03:27:04.511511 (INFO): Hits right @8: 0.85546875\n",
      "2021-08-11 03:27:04.513703 (INFO): Hits @8: 0.85546875\n",
      "2021-08-11 03:27:04.515457 (INFO): Hits left @9: 0.8740234375\n",
      "2021-08-11 03:27:04.519793 (INFO): Hits right @9: 0.876953125\n",
      "2021-08-11 03:27:04.523417 (INFO): Hits @9: 0.87548828125\n",
      "2021-08-11 03:27:04.538880 (INFO): Hits left @10: 0.890625\n",
      "2021-08-11 03:27:04.562427 (INFO): Hits right @10: 0.8984375\n",
      "2021-08-11 03:27:04.606109 (INFO): Hits @10: 0.89453125\n",
      "2021-08-11 03:27:04.608759 (INFO): Mean rank left: 4.490234375\n",
      "2021-08-11 03:27:04.609519 (INFO): Mean rank right: 4.8310546875\n",
      "2021-08-11 03:27:04.613900 (INFO): Mean rank: 4.66064453125\n",
      "2021-08-11 03:27:04.628717 (INFO): Mean reciprocal rank left: 0.577752970770029\n",
      "2021-08-11 03:27:04.643724 (INFO): Mean reciprocal rank right: 0.5352379054856574\n",
      "2021-08-11 03:27:04.655138 (INFO): Mean reciprocal rank: 0.5564954381278432\n",
      "saving best model to saved_models/kinship_ggnn_distmult_0.2_0.25.model\n",
      "2021-08-11 03:27:04.886990 (INFO): \n",
      "2021-08-11 03:27:04.907169 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:27:04.915588 (INFO): test_evaluation\n",
      "2021-08-11 03:27:04.915767 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:27:04.915919 (INFO): \n",
      "2021-08-11 03:43:11.775333 (INFO): Hits left @1: 0.41796875\n",
      "2021-08-11 03:43:11.778256 (INFO): Hits right @1: 0.353515625\n",
      "2021-08-11 03:43:11.779461 (INFO): Hits @1: 0.3857421875\n",
      "2021-08-11 03:43:11.782037 (INFO): Hits left @2: 0.5595703125\n",
      "2021-08-11 03:43:11.783075 (INFO): Hits right @2: 0.482421875\n",
      "2021-08-11 03:43:11.784917 (INFO): Hits @2: 0.52099609375\n",
      "2021-08-11 03:43:11.787001 (INFO): Hits left @3: 0.634765625\n",
      "2021-08-11 03:43:11.788018 (INFO): Hits right @3: 0.5595703125\n",
      "2021-08-11 03:43:11.789051 (INFO): Hits @3: 0.59716796875\n",
      "2021-08-11 03:43:11.793345 (INFO): Hits left @4: 0.7021484375\n",
      "2021-08-11 03:43:11.795306 (INFO): Hits right @4: 0.638671875\n",
      "2021-08-11 03:43:11.797963 (INFO): Hits @4: 0.67041015625\n",
      "2021-08-11 03:43:11.823824 (INFO): Hits left @5: 0.759765625\n",
      "2021-08-11 03:43:11.841074 (INFO): Hits right @5: 0.689453125\n",
      "2021-08-11 03:43:11.843277 (INFO): Hits @5: 0.724609375\n",
      "2021-08-11 03:43:11.845388 (INFO): Hits left @6: 0.80859375\n",
      "2021-08-11 03:43:11.846490 (INFO): Hits right @6: 0.7412109375\n",
      "2021-08-11 03:43:11.847727 (INFO): Hits @6: 0.77490234375\n",
      "2021-08-11 03:43:11.854463 (INFO): Hits left @7: 0.837890625\n",
      "2021-08-11 03:43:11.858796 (INFO): Hits right @7: 0.7900390625\n",
      "2021-08-11 03:43:11.863490 (INFO): Hits @7: 0.81396484375\n",
      "2021-08-11 03:43:11.865393 (INFO): Hits left @8: 0.8603515625\n",
      "2021-08-11 03:43:11.866647 (INFO): Hits right @8: 0.828125\n",
      "2021-08-11 03:43:11.869551 (INFO): Hits @8: 0.84423828125\n",
      "2021-08-11 03:43:11.875140 (INFO): Hits left @9: 0.87890625\n",
      "2021-08-11 03:43:11.878549 (INFO): Hits right @9: 0.869140625\n",
      "2021-08-11 03:43:11.918681 (INFO): Hits @9: 0.8740234375\n",
      "2021-08-11 03:43:11.920847 (INFO): Hits left @10: 0.896484375\n",
      "2021-08-11 03:43:11.922024 (INFO): Hits right @10: 0.8955078125\n",
      "2021-08-11 03:43:11.923294 (INFO): Hits @10: 0.89599609375\n",
      "2021-08-11 03:43:11.926768 (INFO): Mean rank left: 4.6279296875\n",
      "2021-08-11 03:43:11.930617 (INFO): Mean rank right: 4.943359375\n",
      "2021-08-11 03:43:11.934826 (INFO): Mean rank: 4.78564453125\n",
      "2021-08-11 03:43:11.938854 (INFO): Mean reciprocal rank left: 0.5674688288944997\n",
      "2021-08-11 03:43:11.939959 (INFO): Mean reciprocal rank right: 0.508139122751652\n",
      "2021-08-11 03:43:11.941179 (INFO): Mean reciprocal rank: 0.5378039758230758\n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 03:43:26.785729 (INFO): Total epoch time: 0:00:14\n",
      "2021-08-11 03:43:26.790720 (INFO): \n",
      "\n",
      "2021-08-11 03:43:26.794060 (INFO): ########################################\n",
      "2021-08-11 03:43:26.794277 (INFO):           COMPLETED EPOCH: 34                              \n",
      "2021-08-11 03:43:26.794407 (INFO): train Loss: 0.13273\t99% CI: (0.12215, 0.1433), n=23\n",
      "2021-08-11 03:43:26.794530 (INFO): ########################################\n",
      "2021-08-11 03:43:26.794630 (INFO): \n",
      "\n",
      "2021-08-11 03:43:42.587067 (INFO): Total epoch time: 0:00:15\n",
      "2021-08-11 03:43:42.596621 (INFO): \n",
      "\n",
      "2021-08-11 03:43:42.653080 (INFO): ########################################\n",
      "2021-08-11 03:43:42.654317 (INFO):           COMPLETED EPOCH: 35                              \n",
      "2021-08-11 03:43:42.654558 (INFO): train Loss: 0.13083\t99% CI: (0.12016, 0.14149), n=23\n",
      "2021-08-11 03:43:42.658563 (INFO): ########################################\n",
      "2021-08-11 03:43:42.665065 (INFO): \n",
      "\n",
      "2021-08-11 03:43:42.665926 (INFO): \n",
      "2021-08-11 03:43:42.666115 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:43:42.666235 (INFO): dev_evaluation\n",
      "2021-08-11 03:43:42.667227 (INFO): --------------------------------------------------\n",
      "2021-08-11 03:43:42.670644 (INFO): \n",
      "2021-08-11 05:44:15.329288 (INFO): Hits left @1: 0.42578125\n",
      "2021-08-11 05:44:15.329513 (INFO): Hits right @1: 0.384765625\n",
      "2021-08-11 05:44:15.329706 (INFO): Hits @1: 0.4052734375\n",
      "2021-08-11 05:44:15.329819 (INFO): Hits left @2: 0.572265625\n",
      "2021-08-11 05:44:15.329925 (INFO): Hits right @2: 0.484375\n",
      "2021-08-11 05:44:15.330083 (INFO): Hits @2: 0.5283203125\n",
      "2021-08-11 05:44:15.330189 (INFO): Hits left @3: 0.65625\n",
      "2021-08-11 05:44:15.330313 (INFO): Hits right @3: 0.5712890625\n",
      "2021-08-11 05:44:15.330467 (INFO): Hits @3: 0.61376953125\n",
      "2021-08-11 05:44:15.330569 (INFO): Hits left @4: 0.7099609375\n",
      "2021-08-11 05:44:15.330671 (INFO): Hits right @4: 0.6435546875\n",
      "2021-08-11 05:44:15.342204 (INFO): Hits @4: 0.6767578125\n",
      "2021-08-11 05:44:15.378329 (INFO): Hits left @5: 0.755859375\n",
      "2021-08-11 05:44:15.407552 (INFO): Hits right @5: 0.705078125\n",
      "2021-08-11 05:44:15.407721 (INFO): Hits @5: 0.73046875\n",
      "2021-08-11 05:44:15.407824 (INFO): Hits left @6: 0.7890625\n",
      "2021-08-11 05:44:15.408469 (INFO): Hits right @6: 0.7578125\n",
      "2021-08-11 05:44:15.419901 (INFO): Hits @6: 0.7734375\n",
      "2021-08-11 05:44:15.421284 (INFO): Hits left @7: 0.8193359375\n",
      "2021-08-11 05:44:15.427283 (INFO): Hits right @7: 0.802734375\n",
      "2021-08-11 05:44:15.427498 (INFO): Hits @7: 0.81103515625\n",
      "2021-08-11 05:44:15.427604 (INFO): Hits left @8: 0.8427734375\n",
      "2021-08-11 05:44:15.427704 (INFO): Hits right @8: 0.849609375\n",
      "2021-08-11 05:44:15.427880 (INFO): Hits @8: 0.84619140625\n",
      "2021-08-11 05:44:15.427995 (INFO): Hits left @9: 0.8681640625\n",
      "2021-08-11 05:44:15.428092 (INFO): Hits right @9: 0.88671875\n",
      "2021-08-11 05:44:15.428257 (INFO): Hits @9: 0.87744140625\n",
      "2021-08-11 05:44:15.428355 (INFO): Hits left @10: 0.892578125\n",
      "2021-08-11 05:44:15.428454 (INFO): Hits right @10: 0.9140625\n",
      "2021-08-11 05:44:15.428600 (INFO): Hits @10: 0.9033203125\n",
      "2021-08-11 05:44:15.428717 (INFO): Mean rank left: 4.5390625\n",
      "2021-08-11 05:44:15.446651 (INFO): Mean rank right: 4.8349609375\n",
      "2021-08-11 05:44:15.447081 (INFO): Mean rank: 4.68701171875\n",
      "2021-08-11 05:44:15.447187 (INFO): Mean reciprocal rank left: 0.5748260396099876\n",
      "2021-08-11 05:44:15.506655 (INFO): Mean reciprocal rank right: 0.5272472347606698\n",
      "2021-08-11 05:44:15.513295 (INFO): Mean reciprocal rank: 0.5510366371853286\n",
      "2021-08-11 05:44:15.515042 (INFO): \n",
      "2021-08-11 05:44:15.515876 (INFO): --------------------------------------------------\n",
      "2021-08-11 05:44:15.515906 (INFO): test_evaluation\n",
      "2021-08-11 05:44:15.515927 (INFO): --------------------------------------------------\n",
      "2021-08-11 05:44:15.515947 (INFO): \n",
      "2021-08-11 05:44:56.262518 (INFO): Hits left @1: 0.419921875\n",
      "2021-08-11 05:44:56.318755 (INFO): Hits right @1: 0.3623046875\n",
      "2021-08-11 05:44:56.319757 (INFO): Hits @1: 0.39111328125\n",
      "2021-08-11 05:44:56.320284 (INFO): Hits left @2: 0.55859375\n",
      "2021-08-11 05:44:56.322543 (INFO): Hits right @2: 0.4853515625\n",
      "2021-08-11 05:44:56.323939 (INFO): Hits @2: 0.52197265625\n",
      "2021-08-11 05:44:56.326081 (INFO): Hits left @3: 0.6337890625\n",
      "2021-08-11 05:44:56.329629 (INFO): Hits right @3: 0.5732421875\n",
      "2021-08-11 05:44:56.333999 (INFO): Hits @3: 0.603515625\n",
      "2021-08-11 05:44:56.334573 (INFO): Hits left @4: 0.705078125\n",
      "2021-08-11 05:44:56.358593 (INFO): Hits right @4: 0.642578125\n",
      "2021-08-11 05:44:56.402129 (INFO): Hits @4: 0.673828125\n",
      "2021-08-11 05:44:56.466876 (INFO): Hits left @5: 0.759765625\n",
      "2021-08-11 05:44:56.467683 (INFO): Hits right @5: 0.69140625\n",
      "2021-08-11 05:44:56.468502 (INFO): Hits @5: 0.7255859375\n",
      "2021-08-11 05:44:56.470259 (INFO): Hits left @6: 0.8017578125\n",
      "2021-08-11 05:44:56.470886 (INFO): Hits right @6: 0.751953125\n",
      "2021-08-11 05:44:56.471628 (INFO): Hits @6: 0.77685546875\n",
      "2021-08-11 05:44:56.493760 (INFO): Hits left @7: 0.8388671875\n",
      "2021-08-11 05:44:56.495345 (INFO): Hits right @7: 0.79296875\n",
      "2021-08-11 05:44:56.498464 (INFO): Hits @7: 0.81591796875\n",
      "2021-08-11 05:44:56.511095 (INFO): Hits left @8: 0.8623046875\n",
      "2021-08-11 05:44:56.517610 (INFO): Hits right @8: 0.8271484375\n",
      "2021-08-11 05:44:56.522071 (INFO): Hits @8: 0.8447265625\n",
      "2021-08-11 05:44:56.525546 (INFO): Hits left @9: 0.884765625\n",
      "2021-08-11 05:44:56.530865 (INFO): Hits right @9: 0.87109375\n",
      "2021-08-11 05:44:56.537289 (INFO): Hits @9: 0.8779296875\n",
      "2021-08-11 05:44:56.538792 (INFO): Hits left @10: 0.8974609375\n",
      "2021-08-11 05:44:56.543570 (INFO): Hits right @10: 0.896484375\n",
      "2021-08-11 05:44:56.580881 (INFO): Hits @10: 0.89697265625\n",
      "2021-08-11 05:44:56.581800 (INFO): Mean rank left: 4.6171875\n",
      "2021-08-11 05:44:56.582550 (INFO): Mean rank right: 4.8447265625\n",
      "2021-08-11 05:44:56.586415 (INFO): Mean rank: 4.73095703125\n",
      "2021-08-11 05:44:56.590209 (INFO): Mean reciprocal rank left: 0.5683294046593869\n",
      "2021-08-11 05:44:56.594081 (INFO): Mean reciprocal rank right: 0.5148958091175302\n",
      "2021-08-11 05:44:56.598555 (INFO): Mean reciprocal rank: 0.5416126068884586\n",
      "2021-08-11 07:45:05.868247 (INFO): Total epoch time: 2:00:09\n",
      "2021-08-11 07:45:05.884586 (INFO): \n",
      "\n",
      "2021-08-11 07:45:05.890218 (INFO): ########################################\n",
      "2021-08-11 07:45:05.890272 (INFO):           COMPLETED EPOCH: 36                              \n",
      "2021-08-11 07:45:05.890300 (INFO): train Loss: 0.13153\t99% CI: (0.12215, 0.14091), n=23\n",
      "2021-08-11 07:45:05.890786 (INFO): ########################################\n",
      "2021-08-11 07:45:05.890832 (INFO): \n",
      "\n",
      "2021-08-11 07:45:22.172318 (INFO): Total epoch time: 0:00:16\n",
      "2021-08-11 07:45:22.202740 (INFO): \n",
      "\n",
      "2021-08-11 07:45:22.247087 (INFO): ########################################\n",
      "2021-08-11 07:45:22.247562 (INFO):           COMPLETED EPOCH: 37                              \n",
      "2021-08-11 07:45:22.247723 (INFO): train Loss: 0.13852\t99% CI: (0.12663, 0.1504), n=23\n",
      "2021-08-11 07:45:22.250321 (INFO): ########################################\n",
      "2021-08-11 07:45:22.251341 (INFO): \n",
      "\n",
      "2021-08-11 07:45:22.251826 (INFO): \n",
      "2021-08-11 07:45:22.252703 (INFO): --------------------------------------------------\n",
      "2021-08-11 07:45:22.254008 (INFO): dev_evaluation\n",
      "2021-08-11 07:45:22.254835 (INFO): --------------------------------------------------\n",
      "2021-08-11 07:45:22.254962 (INFO): \n",
      "2021-08-11 09:38:31.290937 (INFO): Hits left @1: 0.435546875\n",
      "2021-08-11 09:38:31.292318 (INFO): Hits right @1: 0.3828125\n",
      "2021-08-11 09:38:31.292782 (INFO): Hits @1: 0.4091796875\n",
      "2021-08-11 09:38:31.293103 (INFO): Hits left @2: 0.5791015625\n",
      "2021-08-11 09:38:31.293366 (INFO): Hits right @2: 0.498046875\n",
      "2021-08-11 09:38:31.293725 (INFO): Hits @2: 0.53857421875\n",
      "2021-08-11 09:38:31.315689 (INFO): Hits left @3: 0.6484375\n",
      "2021-08-11 09:38:31.316046 (INFO): Hits right @3: 0.5849609375\n",
      "2021-08-11 09:38:31.316418 (INFO): Hits @3: 0.61669921875\n",
      "2021-08-11 09:38:31.316648 (INFO): Hits left @4: 0.6982421875\n",
      "2021-08-11 09:38:31.316901 (INFO): Hits right @4: 0.6484375\n",
      "2021-08-11 09:38:31.317278 (INFO): Hits @4: 0.67333984375\n",
      "2021-08-11 09:38:31.323983 (INFO): Hits left @5: 0.7548828125\n",
      "2021-08-11 09:38:31.324272 (INFO): Hits right @5: 0.7109375\n",
      "2021-08-11 09:38:31.324787 (INFO): Hits @5: 0.73291015625\n",
      "2021-08-11 09:38:31.342699 (INFO): Hits left @6: 0.7880859375\n",
      "2021-08-11 09:38:31.349053 (INFO): Hits right @6: 0.7685546875\n",
      "2021-08-11 09:38:31.356058 (INFO): Hits @6: 0.7783203125\n",
      "2021-08-11 09:38:31.357228 (INFO): Hits left @7: 0.818359375\n",
      "2021-08-11 09:38:31.363055 (INFO): Hits right @7: 0.8037109375\n",
      "2021-08-11 09:38:31.374025 (INFO): Hits @7: 0.81103515625\n",
      "2021-08-11 09:38:31.374282 (INFO): Hits left @8: 0.83984375\n",
      "2021-08-11 09:38:31.374505 (INFO): Hits right @8: 0.8486328125\n",
      "2021-08-11 09:38:31.374830 (INFO): Hits @8: 0.84423828125\n",
      "2021-08-11 09:38:31.375456 (INFO): Hits left @9: 0.869140625\n",
      "2021-08-11 09:38:31.375782 (INFO): Hits right @9: 0.8837890625\n",
      "2021-08-11 09:38:31.376117 (INFO): Hits @9: 0.87646484375\n",
      "2021-08-11 09:38:31.376591 (INFO): Hits left @10: 0.8935546875\n",
      "2021-08-11 09:38:31.376823 (INFO): Hits right @10: 0.9091796875\n",
      "2021-08-11 09:38:31.377146 (INFO): Hits @10: 0.9013671875\n",
      "2021-08-11 09:38:31.377365 (INFO): Mean rank left: 4.521484375\n",
      "2021-08-11 09:38:31.377576 (INFO): Mean rank right: 4.8095703125\n",
      "2021-08-11 09:38:31.447026 (INFO): Mean rank: 4.66552734375\n",
      "2021-08-11 09:38:31.484302 (INFO): Mean reciprocal rank left: 0.5796234715767435\n",
      "2021-08-11 09:38:31.485158 (INFO): Mean reciprocal rank right: 0.5302875237238108\n",
      "2021-08-11 09:38:31.485517 (INFO): Mean reciprocal rank: 0.5549554976502772\n",
      "2021-08-11 09:38:31.486225 (INFO): \n",
      "2021-08-11 09:38:31.512567 (INFO): --------------------------------------------------\n",
      "2021-08-11 09:38:31.513298 (INFO): test_evaluation\n",
      "2021-08-11 09:38:31.513391 (INFO): --------------------------------------------------\n",
      "2021-08-11 09:38:31.513444 (INFO): \n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 09:38:54.072925 (INFO): Hits left @1: 0.4248046875\n",
      "2021-08-11 09:38:54.089720 (INFO): Hits right @1: 0.3671875\n",
      "2021-08-11 09:38:54.089897 (INFO): Hits @1: 0.39599609375\n",
      "2021-08-11 09:38:54.090008 (INFO): Hits left @2: 0.5595703125\n",
      "2021-08-11 09:38:54.090113 (INFO): Hits right @2: 0.4892578125\n",
      "2021-08-11 09:38:54.090281 (INFO): Hits @2: 0.5244140625\n",
      "2021-08-11 09:38:54.090380 (INFO): Hits left @3: 0.6318359375\n",
      "2021-08-11 09:38:54.090477 (INFO): Hits right @3: 0.572265625\n",
      "2021-08-11 09:38:54.090671 (INFO): Hits @3: 0.60205078125\n",
      "2021-08-11 09:38:54.090786 (INFO): Hits left @4: 0.69921875\n",
      "2021-08-11 09:38:54.091152 (INFO): Hits right @4: 0.6396484375\n",
      "2021-08-11 09:38:54.091306 (INFO): Hits @4: 0.66943359375\n",
      "2021-08-11 09:38:54.091406 (INFO): Hits left @5: 0.76171875\n",
      "2021-08-11 09:38:54.091517 (INFO): Hits right @5: 0.6982421875\n",
      "2021-08-11 09:38:54.091660 (INFO): Hits @5: 0.72998046875\n",
      "2021-08-11 09:38:54.091757 (INFO): Hits left @6: 0.8017578125\n",
      "2021-08-11 09:38:54.091853 (INFO): Hits right @6: 0.7529296875\n",
      "2021-08-11 09:38:54.091997 (INFO): Hits @6: 0.77734375\n",
      "2021-08-11 09:38:54.092093 (INFO): Hits left @7: 0.8369140625\n",
      "2021-08-11 09:38:54.092204 (INFO): Hits right @7: 0.79296875\n",
      "2021-08-11 09:38:54.092609 (INFO): Hits @7: 0.81494140625\n",
      "2021-08-11 09:38:54.092721 (INFO): Hits left @8: 0.861328125\n",
      "2021-08-11 09:38:54.092821 (INFO): Hits right @8: 0.8291015625\n",
      "2021-08-11 09:38:54.092965 (INFO): Hits @8: 0.84521484375\n",
      "2021-08-11 09:38:54.093102 (INFO): Hits left @9: 0.8779296875\n",
      "2021-08-11 09:38:54.093197 (INFO): Hits right @9: 0.873046875\n",
      "2021-08-11 09:38:54.093339 (INFO): Hits @9: 0.87548828125\n",
      "2021-08-11 09:38:54.093474 (INFO): Hits left @10: 0.9013671875\n",
      "2021-08-11 09:38:54.093569 (INFO): Hits right @10: 0.8984375\n",
      "2021-08-11 09:38:54.094462 (INFO): Hits @10: 0.89990234375\n",
      "2021-08-11 09:38:54.094587 (INFO): Mean rank left: 4.599609375\n",
      "2021-08-11 09:38:54.094680 (INFO): Mean rank right: 4.8271484375\n",
      "2021-08-11 09:38:54.094807 (INFO): Mean rank: 4.71337890625\n",
      "2021-08-11 09:38:54.094908 (INFO): Mean reciprocal rank left: 0.5706202633841813\n",
      "2021-08-11 09:38:54.095228 (INFO): Mean reciprocal rank right: 0.5180016414467262\n",
      "2021-08-11 09:38:54.095429 (INFO): Mean reciprocal rank: 0.5443109524154537\n",
      "2021-08-11 09:39:02.719729 (INFO): Total epoch time: 0:00:08\n",
      "2021-08-11 09:39:02.720167 (INFO): \n",
      "\n",
      "2021-08-11 09:39:02.720204 (INFO): ########################################\n",
      "2021-08-11 09:39:02.720229 (INFO):           COMPLETED EPOCH: 38                              \n",
      "2021-08-11 09:39:02.720250 (INFO): train Loss: 0.14189\t99% CI: (0.12979, 0.15398), n=23\n",
      "2021-08-11 09:39:02.720271 (INFO): ########################################\n",
      "2021-08-11 09:39:02.720291 (INFO): \n",
      "\n",
      "2021-08-11 09:39:11.361871 (INFO): Total epoch time: 0:00:08\n",
      "2021-08-11 09:39:11.392726 (INFO): \n",
      "\n",
      "2021-08-11 09:39:11.392784 (INFO): ########################################\n",
      "2021-08-11 09:39:11.392814 (INFO):           COMPLETED EPOCH: 39                              \n",
      "2021-08-11 09:39:11.392838 (INFO): train Loss: 0.12735\t99% CI: (0.11509, 0.13961), n=23\n",
      "2021-08-11 09:39:11.392861 (INFO): ########################################\n",
      "2021-08-11 09:39:11.392884 (INFO): \n",
      "\n",
      "2021-08-11 09:39:11.393017 (INFO): \n",
      "2021-08-11 09:39:11.393052 (INFO): --------------------------------------------------\n",
      "2021-08-11 09:39:11.393078 (INFO): dev_evaluation\n",
      "2021-08-11 09:39:11.393101 (INFO): --------------------------------------------------\n",
      "2021-08-11 09:39:11.393779 (INFO): \n",
      "2021-08-11 09:39:38.950121 (INFO): Hits left @1: 0.4296875\n",
      "2021-08-11 09:39:38.950450 (INFO): Hits right @1: 0.37890625\n",
      "2021-08-11 09:39:38.950631 (INFO): Hits @1: 0.404296875\n",
      "2021-08-11 09:39:38.950747 (INFO): Hits left @2: 0.576171875\n",
      "2021-08-11 09:39:38.950857 (INFO): Hits right @2: 0.501953125\n",
      "2021-08-11 09:39:38.951019 (INFO): Hits @2: 0.5390625\n",
      "2021-08-11 09:39:38.951127 (INFO): Hits left @3: 0.6474609375\n",
      "2021-08-11 09:39:38.951239 (INFO): Hits right @3: 0.5927734375\n",
      "2021-08-11 09:39:38.951401 (INFO): Hits @3: 0.6201171875\n",
      "2021-08-11 09:39:38.951510 (INFO): Hits left @4: 0.703125\n",
      "2021-08-11 09:39:38.952029 (INFO): Hits right @4: 0.6591796875\n",
      "2021-08-11 09:39:38.952209 (INFO): Hits @4: 0.68115234375\n",
      "2021-08-11 09:39:38.952323 (INFO): Hits left @5: 0.7509765625\n",
      "2021-08-11 09:39:38.952433 (INFO): Hits right @5: 0.71484375\n",
      "2021-08-11 09:39:38.952629 (INFO): Hits @5: 0.73291015625\n",
      "2021-08-11 09:39:38.952771 (INFO): Hits left @6: 0.79296875\n",
      "2021-08-11 09:39:38.952891 (INFO): Hits right @6: 0.76953125\n",
      "2021-08-11 09:39:38.953333 (INFO): Hits @6: 0.78125\n",
      "2021-08-11 09:39:38.953461 (INFO): Hits left @7: 0.8232421875\n",
      "2021-08-11 09:39:38.953575 (INFO): Hits right @7: 0.80859375\n",
      "2021-08-11 09:39:38.953738 (INFO): Hits @7: 0.81591796875\n",
      "2021-08-11 09:39:38.953848 (INFO): Hits left @8: 0.8486328125\n",
      "2021-08-11 09:39:38.953956 (INFO): Hits right @8: 0.8525390625\n",
      "2021-08-11 09:39:38.954117 (INFO): Hits @8: 0.8505859375\n",
      "2021-08-11 09:39:38.954225 (INFO): Hits left @9: 0.8671875\n",
      "2021-08-11 09:39:38.954680 (INFO): Hits right @9: 0.8818359375\n",
      "2021-08-11 09:39:38.954848 (INFO): Hits @9: 0.87451171875\n",
      "2021-08-11 09:39:38.954959 (INFO): Hits left @10: 0.8876953125\n",
      "2021-08-11 09:39:38.955070 (INFO): Hits right @10: 0.908203125\n",
      "2021-08-11 09:39:38.955284 (INFO): Hits @10: 0.89794921875\n",
      "2021-08-11 09:39:38.955988 (INFO): Mean rank left: 4.5576171875\n",
      "2021-08-11 09:39:38.956119 (INFO): Mean rank right: 4.7724609375\n",
      "2021-08-11 09:39:38.956272 (INFO): Mean rank: 4.6650390625\n",
      "2021-08-11 09:39:38.956393 (INFO): Mean reciprocal rank left: 0.5763514494362989\n",
      "2021-08-11 09:39:38.961762 (INFO): Mean reciprocal rank right: 0.530419189702076\n",
      "2021-08-11 09:39:38.962424 (INFO): Mean reciprocal rank: 0.5533853195691876\n",
      "2021-08-11 09:39:38.962833 (INFO): \n",
      "2021-08-11 09:39:38.962880 (INFO): --------------------------------------------------\n",
      "2021-08-11 09:39:38.962907 (INFO): test_evaluation\n",
      "2021-08-11 09:39:38.962932 (INFO): --------------------------------------------------\n",
      "2021-08-11 09:39:38.962955 (INFO): \n",
      "2021-08-11 09:40:05.536438 (INFO): Hits left @1: 0.4248046875\n",
      "2021-08-11 09:40:05.537003 (INFO): Hits right @1: 0.3603515625\n",
      "2021-08-11 09:40:05.537181 (INFO): Hits @1: 0.392578125\n",
      "2021-08-11 09:40:05.537295 (INFO): Hits left @2: 0.568359375\n",
      "2021-08-11 09:40:05.537406 (INFO): Hits right @2: 0.484375\n",
      "2021-08-11 09:40:05.537568 (INFO): Hits @2: 0.5263671875\n",
      "2021-08-11 09:40:05.537744 (INFO): Hits left @3: 0.6328125\n",
      "2021-08-11 09:40:05.537879 (INFO): Hits right @3: 0.5634765625\n",
      "2021-08-11 09:40:05.543856 (INFO): Hits @3: 0.59814453125\n",
      "2021-08-11 09:40:05.543992 (INFO): Hits left @4: 0.697265625\n",
      "2021-08-11 09:40:05.544107 (INFO): Hits right @4: 0.642578125\n",
      "2021-08-11 09:40:05.544270 (INFO): Hits @4: 0.669921875\n",
      "2021-08-11 09:40:05.593095 (INFO): Hits left @5: 0.748046875\n",
      "2021-08-11 09:40:05.615630 (INFO): Hits right @5: 0.69921875\n",
      "2021-08-11 09:40:05.615834 (INFO): Hits @5: 0.7236328125\n",
      "2021-08-11 09:40:05.615961 (INFO): Hits left @6: 0.80078125\n",
      "2021-08-11 09:40:05.616076 (INFO): Hits right @6: 0.7490234375\n",
      "2021-08-11 09:40:05.616241 (INFO): Hits @6: 0.77490234375\n",
      "2021-08-11 09:40:05.616349 (INFO): Hits left @7: 0.841796875\n",
      "2021-08-11 09:40:05.617258 (INFO): Hits right @7: 0.7900390625\n",
      "2021-08-11 09:40:05.617444 (INFO): Hits @7: 0.81591796875\n",
      "2021-08-11 09:40:05.617563 (INFO): Hits left @8: 0.8681640625\n",
      "2021-08-11 09:40:05.617676 (INFO): Hits right @8: 0.837890625\n",
      "2021-08-11 09:40:05.617840 (INFO): Hits @8: 0.85302734375\n",
      "2021-08-11 09:40:05.618256 (INFO): Hits left @9: 0.880859375\n",
      "2021-08-11 09:40:05.618368 (INFO): Hits right @9: 0.8798828125\n",
      "2021-08-11 09:40:05.618532 (INFO): Hits @9: 0.88037109375\n",
      "2021-08-11 09:40:05.618642 (INFO): Hits left @10: 0.8974609375\n",
      "2021-08-11 09:40:05.618752 (INFO): Hits right @10: 0.9013671875\n",
      "2021-08-11 09:40:05.618915 (INFO): Hits @10: 0.8994140625\n",
      "2021-08-11 09:40:05.619042 (INFO): Mean rank left: 4.609375\n",
      "2021-08-11 09:40:05.619160 (INFO): Mean rank right: 4.8310546875\n",
      "2021-08-11 09:40:05.619632 (INFO): Mean rank: 4.72021484375\n",
      "2021-08-11 09:40:05.619792 (INFO): Mean reciprocal rank left: 0.5716509884769146\n",
      "2021-08-11 09:40:05.619994 (INFO): Mean reciprocal rank right: 0.5133430299100239\n",
      "2021-08-11 09:40:05.620395 (INFO): Mean reciprocal rank: 0.5424970091934693\n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2021-08-11 09:40:16.080395 (INFO): Total epoch time: 0:00:10\n",
      "2021-08-11 09:40:16.081148 (INFO): \n",
      "\n",
      "2021-08-11 09:40:16.081187 (INFO): ########################################\n",
      "2021-08-11 09:40:16.081212 (INFO):           COMPLETED EPOCH: 40                              \n",
      "2021-08-11 09:40:16.081235 (INFO): train Loss: 0.1379\t99% CI: (0.12809, 0.1477), n=23\n",
      "2021-08-11 09:40:16.081255 (INFO): ########################################\n",
      "2021-08-11 09:40:16.081276 (INFO): \n",
      "\n",
      "2021-08-11 09:40:27.840489 (INFO): Total epoch time: 0:00:11\n",
      "2021-08-11 09:40:27.891332 (INFO): \n",
      "\n",
      "2021-08-11 09:40:27.891457 (INFO): ########################################\n",
      "2021-08-11 09:40:27.891505 (INFO):           COMPLETED EPOCH: 41                              \n",
      "2021-08-11 09:40:27.891543 (INFO): train Loss: 0.12752\t99% CI: (0.116, 0.13904), n=23\n",
      "2021-08-11 09:40:27.891579 (INFO): ########################################\n",
      "2021-08-11 09:40:27.891613 (INFO): \n",
      "\n",
      "2021-08-11 09:40:27.891784 (INFO): \n",
      "2021-08-11 09:40:27.891832 (INFO): --------------------------------------------------\n",
      "2021-08-11 09:40:27.891870 (INFO): dev_evaluation\n",
      "2021-08-11 09:40:27.891905 (INFO): --------------------------------------------------\n",
      "2021-08-11 09:40:27.891941 (INFO): \n",
      "2021-08-11 09:40:52.895978 (INFO): Hits left @1: 0.423828125\n",
      "2021-08-11 09:40:52.924177 (INFO): Hits right @1: 0.38671875\n",
      "2021-08-11 09:40:52.924373 (INFO): Hits @1: 0.4052734375\n",
      "2021-08-11 09:40:52.924491 (INFO): Hits left @2: 0.5712890625\n",
      "2021-08-11 09:40:52.924602 (INFO): Hits right @2: 0.494140625\n",
      "2021-08-11 09:40:52.924763 (INFO): Hits @2: 0.53271484375\n",
      "2021-08-11 09:40:52.924873 (INFO): Hits left @3: 0.65625\n",
      "2021-08-11 09:40:52.924980 (INFO): Hits right @3: 0.580078125\n",
      "2021-08-11 09:40:52.925138 (INFO): Hits @3: 0.6181640625\n",
      "2021-08-11 09:40:52.925248 (INFO): Hits left @4: 0.703125\n",
      "2021-08-11 09:40:52.925354 (INFO): Hits right @4: 0.650390625\n",
      "2021-08-11 09:40:52.925824 (INFO): Hits @4: 0.6767578125\n",
      "2021-08-11 09:40:52.925951 (INFO): Hits left @5: 0.74609375\n",
      "2021-08-11 09:40:52.926067 (INFO): Hits right @5: 0.7119140625\n",
      "2021-08-11 09:40:52.926230 (INFO): Hits @5: 0.72900390625\n",
      "2021-08-11 09:40:52.926339 (INFO): Hits left @6: 0.78515625\n",
      "2021-08-11 09:40:52.926445 (INFO): Hits right @6: 0.76953125\n",
      "2021-08-11 09:40:52.926606 (INFO): Hits @6: 0.77734375\n",
      "2021-08-11 09:40:52.926714 (INFO): Hits left @7: 0.818359375\n",
      "2021-08-11 09:40:52.926850 (INFO): Hits right @7: 0.8125\n",
      "2021-08-11 09:40:52.927011 (INFO): Hits @7: 0.8154296875\n",
      "2021-08-11 09:40:52.927121 (INFO): Hits left @8: 0.845703125\n",
      "2021-08-11 09:40:52.927228 (INFO): Hits right @8: 0.857421875\n",
      "2021-08-11 09:40:52.927386 (INFO): Hits @8: 0.8515625\n",
      "2021-08-11 09:40:52.927493 (INFO): Hits left @9: 0.8701171875\n",
      "2021-08-11 09:40:52.927599 (INFO): Hits right @9: 0.892578125\n",
      "2021-08-11 09:40:52.927760 (INFO): Hits @9: 0.88134765625\n",
      "2021-08-11 09:40:52.927869 (INFO): Hits left @10: 0.8818359375\n",
      "2021-08-11 09:40:52.927976 (INFO): Hits right @10: 0.9111328125\n",
      "2021-08-11 09:40:52.928136 (INFO): Hits @10: 0.896484375\n",
      "2021-08-11 09:40:52.928736 (INFO): Mean rank left: 4.5498046875\n",
      "2021-08-11 09:40:52.928853 (INFO): Mean rank right: 4.7734375\n",
      "2021-08-11 09:40:52.929005 (INFO): Mean rank: 4.66162109375\n",
      "2021-08-11 09:40:52.929258 (INFO): Mean reciprocal rank left: 0.5730223121713727\n",
      "2021-08-11 09:40:52.929975 (INFO): Mean reciprocal rank right: 0.5317686715262253\n",
      "2021-08-11 09:40:52.930510 (INFO): Mean reciprocal rank: 0.552395491848799\n",
      "2021-08-11 09:40:52.930970 (INFO): \n",
      "2021-08-11 09:40:52.931016 (INFO): --------------------------------------------------\n",
      "2021-08-11 09:40:52.931043 (INFO): test_evaluation\n",
      "2021-08-11 09:40:52.931984 (INFO): --------------------------------------------------\n",
      "2021-08-11 09:40:52.932275 (INFO): \n",
      "2021-08-11 09:41:21.128570 (INFO): Hits left @1: 0.421875\n",
      "2021-08-11 09:41:21.129043 (INFO): Hits right @1: 0.36328125\n",
      "2021-08-11 09:41:21.129276 (INFO): Hits @1: 0.392578125\n",
      "2021-08-11 09:41:21.129412 (INFO): Hits left @2: 0.5537109375\n",
      "2021-08-11 09:41:21.129532 (INFO): Hits right @2: 0.486328125\n",
      "2021-08-11 09:41:21.129762 (INFO): Hits @2: 0.52001953125\n",
      "2021-08-11 09:41:21.129861 (INFO): Hits left @3: 0.6318359375\n",
      "2021-08-11 09:41:21.129958 (INFO): Hits right @3: 0.5791015625\n",
      "2021-08-11 09:41:21.130721 (INFO): Hits @3: 0.60546875\n",
      "2021-08-11 09:41:21.131064 (INFO): Hits left @4: 0.6923828125\n",
      "2021-08-11 09:41:21.131180 (INFO): Hits right @4: 0.6337890625\n",
      "2021-08-11 09:41:21.131370 (INFO): Hits @4: 0.6630859375\n",
      "2021-08-11 09:41:21.131697 (INFO): Hits left @5: 0.7470703125\n",
      "2021-08-11 09:41:21.131826 (INFO): Hits right @5: 0.6962890625\n",
      "2021-08-11 09:41:21.131979 (INFO): Hits @5: 0.7216796875\n",
      "2021-08-11 09:41:21.132081 (INFO): Hits left @6: 0.7939453125\n",
      "2021-08-11 09:41:21.132181 (INFO): Hits right @6: 0.7568359375\n",
      "2021-08-11 09:41:21.132377 (INFO): Hits @6: 0.775390625\n",
      "2021-08-11 09:41:21.132474 (INFO): Hits left @7: 0.83203125\n",
      "2021-08-11 09:41:21.132570 (INFO): Hits right @7: 0.8037109375\n",
      "2021-08-11 09:41:21.132713 (INFO): Hits @7: 0.81787109375\n",
      "2021-08-11 09:41:21.133140 (INFO): Hits left @8: 0.85546875\n",
      "2021-08-11 09:41:21.133251 (INFO): Hits right @8: 0.8310546875\n",
      "2021-08-11 09:41:21.133403 (INFO): Hits @8: 0.84326171875\n",
      "2021-08-11 09:41:21.133505 (INFO): Hits left @9: 0.880859375\n",
      "2021-08-11 09:41:21.133604 (INFO): Hits right @9: 0.87109375\n",
      "2021-08-11 09:41:21.133768 (INFO): Hits @9: 0.8759765625\n",
      "2021-08-11 09:41:21.133866 (INFO): Hits left @10: 0.8955078125\n",
      "2021-08-11 09:41:21.133962 (INFO): Hits right @10: 0.900390625\n",
      "2021-08-11 09:41:21.134107 (INFO): Hits @10: 0.89794921875\n",
      "2021-08-11 09:41:21.136067 (INFO): Mean rank left: 4.6875\n",
      "2021-08-11 09:41:21.136217 (INFO): Mean rank right: 4.822265625\n",
      "2021-08-11 09:41:21.136359 (INFO): Mean rank: 4.7548828125\n",
      "2021-08-11 09:41:21.136642 (INFO): Mean reciprocal rank left: 0.5668115792379946\n",
      "2021-08-11 09:41:21.136838 (INFO): Mean reciprocal rank right: 0.5160930438480237\n",
      "2021-08-11 09:41:21.136989 (INFO): Mean reciprocal rank: 0.5414523115430091\n",
      "2021-08-11 09:41:32.452488 (INFO): Total epoch time: 0:00:11\n",
      "2021-08-11 09:41:32.453975 (INFO): \n",
      "\n",
      "2021-08-11 09:41:32.454371 (INFO): ########################################\n",
      "2021-08-11 09:41:32.454432 (INFO):           COMPLETED EPOCH: 42                              \n",
      "2021-08-11 09:41:32.454473 (INFO): train Loss: 0.13753\t99% CI: (0.12796, 0.1471), n=23\n",
      "2021-08-11 09:41:32.454509 (INFO): ########################################\n",
      "2021-08-11 09:41:32.454545 (INFO): \n",
      "\n"
     ]
    }
   ],
   "source": [
    "main(args, model_path)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "id": "dd7166d6",
   "metadata": {},
   "outputs": [],
   "source": []
  }
 ],
 "metadata": {
  "kernelspec": {
   "display_name": "Python 3 (ipykernel)",
   "language": "python",
   "name": "python3"
  },
  "language_info": {
   "codemirror_mode": {
    "name": "ipython",
    "version": 3
   },
   "file_extension": ".py",
   "mimetype": "text/x-python",
   "name": "python",
   "nbconvert_exporter": "python",
   "pygments_lexer": "ipython3",
   "version": "3.7.11"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 5
}
